grpc-node icon indicating copy to clipboard operation
grpc-node copied to clipboard

Published 20 hours ago • verified publisher icon grpc

dns_resolver not triggered after GOAWAY received in version 1.10.11

Open arkonchik opened this issue 5 months ago • 1 comments

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

  • server image version node:21-alpine
  • client image version node:14
  • bug reproduced in grpc/grpc-js 1.10.11

Additional context

logs at 1.10.10

Attaching to sample-node-client-1
sample-node-client-1  | 
sample-node-client-1  | > [email protected] 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  | > [email protected] 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}

arkonchik avatar Sep 12 '24 14:09 arkonchik