Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

dns_resolver not triggered after GOAWAY received in version 1.10.11 #2824

Open
arkonchik opened this issue Sep 12, 2024 · 1 comment
Open

dns_resolver not triggered after GOAWAY received in version 1.10.11 #2824

arkonchik opened this issue Sep 12, 2024 · 1 comment
Labels
package: @grpc/grpc-js

Comments

@arkonchik
Copy link

arkonchik commented Sep 12, 2024 •
edited by murgatroid99
Loading

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}
@murgatroid99 murgatroid99 mentioned this issue Sep 12, 2024
Merged
@murgatroid99
Copy link
Member

This should work now in 1.11.3.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
package: @grpc/grpc-js
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@murgatroid99 @arkonchik