search

grpc / grpc-node

gRPC for Node.js
https://grpc.io
Apache License 2.0
4.48k stars 648 forks source link

dns_resolver not triggered after GOAWAY received in version 1.10.11 #2824

Open arkonchik opened 1 month ago

arkonchik commented 1 month ago

Problem description

So, we are relly that dns_resolver is appear once max connection age was expired And this behavior work until version 1.10.10, in 1.10.11 it don't work

Reproduction steps

create any on grpc client set up env variable on client GRPC_VERBOSITY=DEBUG GRPC_TRACE=transport,dns_resolver

//pseudo client code

const options = {
    //sets round robin strategy
    'grpc.service_config': JSON.stringify({ loadBalancingConfig: [{ round_robin: {} }] }),
    'grpc.dns_min_time_between_resolutions_ms': 10 * 1000, //this is needed to refresh dns records every 10 seconds
};

const client = new EchoServiceClient('be-servers:9999', credentials.createInsecure(), options);

let i = 0;
setInterval(() => {
    i++
    const req = new EchoRequest()
    const start = Date.now();
    req.setMessage('with_timeout');
    client.echo(req, {deadline: Date.now() + 20000} as any, (e, resp) => {
        if (e) {
            console.log(e);
        } else {
            console.log('call number ' + i + ', server response = ' + resp.getMessage() + ' response time = ' + (Date.now() - start));
        }
    });
}, 1000);

//pseudo server code

const server = new Server({
    'grpc.max_connection_age_ms': 20 * 1000, //this is ttl of connection, afterwards a connection will be dropped
    'grpc.max_connection_age_grace_ms': 1 * 1000, //this is a grace time to complete query before expiring a connection
    //time is 20 seconds when client deadline is 10 seconds, just in case
});
server.addService(EchoServiceService, {
    echo: (call: any, callback: any) => {
        const message = call.request.getMessage();
        //console.log("Message received "+ message);
        const resp = new EchoResponse();
        resp.setMessage(message + ' from (nodejs) hostname ' + process.env.HOSTNAME);
        if (message == 'with_timeout') {
            setTimeout(() => {
                callback(null, resp);
            }, 10000);
        } else if (message == 'with_short_timeout') {
            setTimeout(() => {
                callback(null, resp);
            }, 500);
        }else {
            callback(null, resp);
        }
    },
});

server.bindAsync('0.0.0.0:9999', ServerCredentials.createInsecure(), () => {
    console.log("grpc server started on port 9999");
    server.start();
});

So, you won't see any dns_resolver event each 20sec( 'grpc.max_connection_age_ms': 20 * 1000)

Environment

Additional context

logs at 1.10.10

Attaching to sample-node-client-1
sample-node-client-1  | 
sample-node-client-1  | > grpc-client-lb-poc@1.0.0 start-client /home/node/app
sample-node-client-1  | > ts-node ./index.ts
sample-node-client-1  | 
sample-node-client-1  | D 2024-09-12T14:40:28.200Z | v1.10.10 18 | dns_resolver | Resolver constructed for target dns:be-servers:9999
sample-node-client-1  | D 2024-09-12T14:40:28.718Z | v1.10.10 18 | dns_resolver | Looking up DNS hostname be-servers
sample-node-client-1  | D 2024-09-12T14:40:28.722Z | v1.10.10 18 | dns_resolver | Resolved addresses for target dns:be-servers:9999: [172.31.0.4:9999,172.31.0.3:9999]
sample-node-client-1  | D 2024-09-12T14:40:28.726Z | v1.10.10 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.4:9999
sample-node-client-1  | D 2024-09-12T14:40:28.727Z | v1.10.10 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.3:9999
sample-node-client-1  | D 2024-09-12T14:40:28.732Z | v1.10.10 18 | transport | (2) 172.31.0.3:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:28.732Z | v1.10.10 18 | transport | (1) 172.31.0.4:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:38.411Z | v1.10.10 18 | transport | (1) 172.31.0.4:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:38.412Z | v1.10.10 18 | dns_resolver | resolution update delayed by "min time between resolutions" rate limit
sample-node-client-1  | D 2024-09-12T14:40:38.413Z | v1.10.10 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.4:9999
sample-node-client-1  | D 2024-09-12T14:40:38.414Z | v1.10.10 18 | transport | (3) 172.31.0.4:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:38.720Z | v1.10.10 18 | dns_resolver | Looking up DNS hostname be-servers
sample-node-client-1  | D 2024-09-12T14:40:38.722Z | v1.10.10 18 | dns_resolver | Resolved addresses for target dns:be-servers:9999: [172.31.0.4:9999,172.31.0.3:9999]
sample-node-client-1  | D 2024-09-12T14:40:39.510Z | v1.10.10 18 | transport | (2) 172.31.0.3:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:39.512Z | v1.10.10 18 | dns_resolver | resolution update delayed by "min time between resolutions" rate limit
sample-node-client-1  | D 2024-09-12T14:40:39.512Z | v1.10.10 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.3:9999
sample-node-client-1  | D 2024-09-12T14:40:39.515Z | v1.10.10 18 | transport | (4) 172.31.0.3:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}

logs at 1.10.11

sample-node-client-1  | > grpc-client-lb-poc@1.0.0 start-client /home/node/app
sample-node-client-1  | > ts-node ./index.ts
sample-node-client-1  | 
sample-node-client-1  | D 2024-09-12T14:39:49.253Z | v1.10.11 18 | dns_resolver | Resolver constructed for target dns:be-servers:9999
sample-node-client-1  | D 2024-09-12T14:39:49.773Z | v1.10.11 18 | dns_resolver | Looking up DNS hostname be-servers
sample-node-client-1  | D 2024-09-12T14:39:49.778Z | v1.10.11 18 | dns_resolver | Resolved addresses for target dns:be-servers:9999: [172.31.0.4:9999,172.31.0.3:9999]
sample-node-client-1  | D 2024-09-12T14:39:49.782Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.4:9999
sample-node-client-1  | D 2024-09-12T14:39:49.783Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.3:9999
sample-node-client-1  | D 2024-09-12T14:39:49.789Z | v1.10.11 18 | transport | (1) 172.31.0.4:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:39:49.789Z | v1.10.11 18 | transport | (2) 172.31.0.3:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}

sample-node-client-1  | D 2024-09-12T14:40:00.614Z | v1.10.11 18 | transport | (2) 172.31.0.3:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:00.616Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.3:9999
sample-node-client-1  | D 2024-09-12T14:40:00.618Z | v1.10.11 18 | transport | (1) 172.31.0.4:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:00.619Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.4:9999
sample-node-client-1  | D 2024-09-12T14:40:00.620Z | v1.10.11 18 | transport | (3) 172.31.0.3:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:00.621Z | v1.10.11 18 | transport | (4) 172.31.0.4:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:09.794Z | v1.10.11 18 | transport | (2) 172.31.0.3:9999 session closed
sample-node-client-1  | D 2024-09-12T14:40:09.952Z | v1.10.11 18 | transport | (4) 172.31.0.4:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:09.953Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.4:9999
sample-node-client-1  | D 2024-09-12T14:40:09.954Z | v1.10.11 18 | transport | (5) 172.31.0.4:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
sample-node-client-1  | D 2024-09-12T14:40:10.290Z | v1.10.11 18 | transport | (1) 172.31.0.4:9999 session closed
sample-node-client-1  | D 2024-09-12T14:40:10.699Z | v1.10.11 18 | transport | (3) 172.31.0.3:9999 connection closed by GOAWAY with code 0 and data max_age
sample-node-client-1  | D 2024-09-12T14:40:10.701Z | v1.10.11 18 | transport | dns:be-servers:9999 creating HTTP/2 session to 172.31.0.3:9999
sample-node-client-1  | D 2024-09-12T14:40:10.703Z | v1.10.11 18 | transport | (6) 172.31.0.3:9999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
murgatroid99 commented 1 month ago

This should work now in 1.11.3.