search

grpc / grpc-node

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

Client re-using broken connection #2853

Open rnza0u opened 2 weeks ago

rnza0u commented 2 weeks ago

Problem description

When i shut down my GRPC server, it invalidates all TCP connections bound to it, which is normal behavior.

However, it seems like the GRPC client still wants to re-use the dead connections.

After restarting the server and trying to send calls from the client, i get this error:

Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe

I tried setting grpc.enable_retries to 1, that did not work.

I also tried to play with the keep alive settings so maybe the client would invalidate the connections and create new ones for further calls :

"grpc.keepalive_time_ms": 10000,
"grpc.keepalive_timeout_ms": 5000,

But then i randomly get: Received RST_STREAM with code 2 triggered by internal client error: The pending stream has been canceled.

It seems like the client is always trying to use dead connections and is not creating new ones.

What are the steps in order to overcome this ? Am i missing something ?

Thanks !

Environment

murgatroid99 commented 1 week ago

I have not seen this behavior before. Please reproduce this behavior with the environment variables GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG set, and share the logs. That will be the best way to get an idea of what exactly is happening there.

rnza0u commented 1 week ago

Yes.

Here is how i tested it:

1) Make one request with the server up. 2) Turn off the server 3) Make a few (failed) requests from the client. 4) Restart the server 5) Make a new request from the client (fails in Deno, but not in Node).

I am now providing logs for both Node and Deno tests.

Here are the logs in Node:

1st successful request (server up):

D 2024-11-18T22:01:23.392Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:01:23.392Z | v1.12.2 1087900 | connectivity_state | (1) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:01:23.393Z | v1.12.2 1087900 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:01:23.393Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:01:23.394Z | v1.12.2 1087900 | channel_stacktrace | (1) Channel constructed 
    at new InternalChannel (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
    at file:///home/rnzaou/ciron/grpc-bug/go.mjs:50:1
    at ModuleJob.run (node:internal/modules/esm/module_job:234:25)
    at async ModuleLoader.import (node:internal/modules/esm/loader:473:24)
    at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:123:5)
D 2024-11-18T22:01:23.394Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 createResolvingCall [0] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:01:23.394Z | v1.12.2 1087900 | resolving_call | [0] Created
D 2024-11-18T22:01:23.394Z | v1.12.2 1087900 | resolving_call | [0] Deadline: Infinity
D 2024-11-18T22:01:23.395Z | v1.12.2 1087900 | resolving_call | [0] start called
D 2024-11-18T22:01:23.395Z | v1.12.2 1087900 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:01:23.395Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:23.396Z | v1.12.2 1087900 | connectivity_state | (1) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:23.396Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:01:23.396Z | v1.12.2 1087900 | resolving_call | [0] startRead called
D 2024-11-18T22:01:23.397Z | v1.12.2 1087900 | resolving_call | [0] write() called with message of length 23
D 2024-11-18T22:01:23.397Z | v1.12.2 1087900 | resolving_call | [0] halfClose called
D 2024-11-18T22:01:23.402Z | v1.12.2 1087900 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:01:23.403Z | v1.12.2 1087900 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:01:23.404Z | v1.12.2 1087900 | subchannel | (1) 127.0.0.1:5999 Subchannel constructed with options {}
D 2024-11-18T22:01:23.404Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 0 -> 1
D 2024-11-18T22:01:23.404Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 1 -> 2
D 2024-11-18T22:01:23.404Z | v1.12.2 1087900 | pick_first | Start connecting to subchannel with address 127.0.0.1:5999
D 2024-11-18T22:01:23.404Z | v1.12.2 1087900 | pick_first | IDLE -> CONNECTING
D 2024-11-18T22:01:23.405Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:01:23.405Z | v1.12.2 1087900 | connectivity_state | (1) dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:01:23.405Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:01:23.405Z | v1.12.2 1087900 | subchannel | (1) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:23.406Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:23.407Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 createRetryingCall [1] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:01:23.407Z | v1.12.2 1087900 | resolving_call | [0] Created child [1]
D 2024-11-18T22:01:23.407Z | v1.12.2 1087900 | retrying_call | [1] start called
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 createLoadBalancingCall [2] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | retrying_call | [1] Created child call [2] for attempt 1
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | load_balancing_call | [2] start called
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | load_balancing_call | [2] Pick called
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | load_balancing_call | [2] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-11-18T22:01:23.408Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-11-18T22:01:23.409Z | v1.12.2 1087900 | retrying_call | [1] startRead called
D 2024-11-18T22:01:23.409Z | v1.12.2 1087900 | load_balancing_call | [2] startRead called
D 2024-11-18T22:01:23.409Z | v1.12.2 1087900 | retrying_call | [1] write() called with message of length 28
D 2024-11-18T22:01:23.409Z | v1.12.2 1087900 | load_balancing_call | [2] write() called with message of length 28
D 2024-11-18T22:01:23.409Z | v1.12.2 1087900 | retrying_call | [1] halfClose called
D 2024-11-18T22:01:23.411Z | v1.12.2 1087900 | subchannel | (1) 127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:01:23.411Z | v1.12.2 1087900 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:01:23.411Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 2 -> 3
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 3 -> 2
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | pick_first | CONNECTING -> READY
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | channel | (1) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | load_balancing_call | [2] Pick called
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | load_balancing_call | [2] Pick result: COMPLETE subchannel: (1) 127.0.0.1:5999 status: undefined undefined
D 2024-11-18T22:01:23.412Z | v1.12.2 1087900 | connectivity_state | (1) dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:01:23.413Z | v1.12.2 1087900 | transport_flowctrl | (1) 127.0.0.1:5999 local window size: 65535 remote window size: 65535
D 2024-11-18T22:01:23.413Z | v1.12.2 1087900 | transport_internals | (1) 127.0.0.1:5999 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-11-18T22:01:23.414Z | v1.12.2 1087900 | load_balancing_call | [2] Created child call [3]
D 2024-11-18T22:01:23.414Z | v1.12.2 1087900 | subchannel_call | [3] write() called with message of length 28
D 2024-11-18T22:01:23.414Z | v1.12.2 1087900 | subchannel_call | [3] sending data chunk of length 28
D 2024-11-18T22:01:23.415Z | v1.12.2 1087900 | load_balancing_call | [2] halfClose called
D 2024-11-18T22:01:23.415Z | v1.12.2 1087900 | subchannel_call | [3] end() called
D 2024-11-18T22:01:23.415Z | v1.12.2 1087900 | subchannel_call | [3] calling end() on HTTP/2 stream
D 2024-11-18T22:01:23.415Z | v1.12.2 1087900 | transport | (1) 127.0.0.1:5999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2024-11-18T22:01:23.428Z | v1.12.2 1087900 | subchannel_call | [3] Received server headers:
                :status: 200
                content-type: application/grpc
                date: Mon, 18 Nov 2024 22:01:23 GMT

D 2024-11-18T22:01:23.428Z | v1.12.2 1087900 | load_balancing_call | [2] Received metadata
D 2024-11-18T22:01:23.428Z | v1.12.2 1087900 | retrying_call | [1] Received metadata from child [2]
D 2024-11-18T22:01:23.428Z | v1.12.2 1087900 | retrying_call | [1] Committing call [2] at index 0
D 2024-11-18T22:01:23.429Z | v1.12.2 1087900 | resolving_call | [0] Received metadata
D 2024-11-18T22:01:23.429Z | v1.12.2 1087900 | subchannel_call | [3] receive HTTP/2 data frame of length 131
D 2024-11-18T22:01:23.429Z | v1.12.2 1087900 | subchannel_call | [3] parsed message of length 131
D 2024-11-18T22:01:23.429Z | v1.12.2 1087900 | subchannel_call | [3] pushing to reader message of length 131
D 2024-11-18T22:01:23.430Z | v1.12.2 1087900 | load_balancing_call | [2] Received message
D 2024-11-18T22:01:23.430Z | v1.12.2 1087900 | retrying_call | [1] Received message from child [2]
D 2024-11-18T22:01:23.430Z | v1.12.2 1087900 | resolving_call | [0] Received message
D 2024-11-18T22:01:23.430Z | v1.12.2 1087900 | resolving_call | [0] Finished filtering received message
D 2024-11-18T22:01:23.432Z | v1.12.2 1087900 | subchannel_call | [3] Received server trailers:
                grpc-status: 0

D 2024-11-18T22:01:23.432Z | v1.12.2 1087900 | subchannel_call | [3] received status code 0 from server
D 2024-11-18T22:01:23.432Z | v1.12.2 1087900 | subchannel_call | [3] ended with status: code=0 details=""
D 2024-11-18T22:01:23.432Z | v1.12.2 1087900 | load_balancing_call | [2] Received status
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | load_balancing_call | [2] ended with status: code=0 details="" start time=2024-11-18T22:01:23.408Z
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | retrying_call | [1] Received status from child [2]
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | retrying_call | [1] state=COMMITTED handling status with progress PROCESSED from child [2] in state ACTIVE
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | retrying_call | [1] ended with status: code=0 details="" start time=2024-11-18T22:01:23.407Z
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | resolving_call | [0] Received status
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | resolving_call | [0] ended with status: code=0 details=""
D 2024-11-18T22:01:23.433Z | v1.12.2 1087900 | subchannel_call | [3] HTTP/2 stream closed with code 0

Then i'm closing the server, i get these logs in real time:

D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | transport | (1) 127.0.0.1:5999 session closed
D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | subchannel | (1) 127.0.0.1:5999 READY -> IDLE
D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 2 -> 1
D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | pick_first | READY -> IDLE
D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 READY -> IDLE
D 2024-11-18T22:01:25.891Z | v1.12.2 1087900 | connectivity_state | (1) dns:127.0.0.1:5999 READY -> IDLE
D 2024-11-18T22:01:33.404Z | v1.12.2 1087900 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 1 -> 0

Second request (failed because server is offline):

D 2024-11-18T22:01:53.434Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:01:53.434Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:01:53.434Z | v1.12.2 1087900 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | channel_stacktrace | (2) Channel constructed 
    at new InternalChannel (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 createResolvingCall [4] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | resolving_call | [4] Created
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | resolving_call | [4] Deadline: Infinity
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | resolving_call | [4] start called
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:53.435Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | resolving_call | [4] startRead called
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | resolving_call | [4] write() called with message of length 23
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | resolving_call | [4] halfClose called
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 Subchannel constructed with options {}
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | subchannel_refcount | (2) 127.0.0.1:5999 refcount 0 -> 1
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | subchannel_refcount | (2) 127.0.0.1:5999 refcount 1 -> 2
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | pick_first | Start connecting to subchannel with address 127.0.0.1:5999
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | pick_first | IDLE -> CONNECTING
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:01:53.436Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 createRetryingCall [5] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | resolving_call | [4] Created child [5]
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | retrying_call | [5] start called
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 createLoadBalancingCall [6] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | retrying_call | [5] Created child call [6] for attempt 1
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | load_balancing_call | [6] start called
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | load_balancing_call | [6] Pick called
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | load_balancing_call | [6] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | retrying_call | [5] startRead called
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | load_balancing_call | [6] startRead called
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | retrying_call | [5] write() called with message of length 28
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | load_balancing_call | [6] write() called with message of length 28
D 2024-11-18T22:01:53.437Z | v1.12.2 1087900 | retrying_call | [5] halfClose called
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)"
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | channel | (2) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:01:53.438Z | v1.12.2 1087900 | load_balancing_call | [6] Pick called
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | load_balancing_call | [6] Pick result: TRANSIENT_FAILURE subchannel: null status: 14 No connection established. Last error: connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | load_balancing_call | [6] ended with status: code=14 details="No connection established. Last error: connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)" start time=2024-11-18T22:01:53.437Z
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | retrying_call | [5] Received status from child [6]
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | retrying_call | [5] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [6] in state ACTIVE
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | retrying_call | [5] ended with status: code=14 details="No connection established. Last error: connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)" start time=2024-11-18T22:01:53.437Z
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | resolving_call | [4] Received status
D 2024-11-18T22:01:53.439Z | v1.12.2 1087900 | resolving_call | [4] ended with status: code=14 details="No connection established. Last error: connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)"
14 UNAVAILABLE: No connection established. Last error: connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:53.438Z)
D 2024-11-18T22:01:55.665Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> CONNECTING
D 2024-11-18T22:01:55.665Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:55.665Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:55.666Z)"
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | resolving_load_balancer | requestReresolution delayed by backoff timer until 2024-11-18T22:01:54.438Z
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> IDLE
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:01:55.666Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:55.666Z)"
D 2024-11-18T22:01:55.667Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:55.667Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:55.667Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.590Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> CONNECTING
D 2024-11-18T22:01:57.590Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:57.590Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:57.591Z)"
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | resolving_load_balancer | requestReresolution delayed by backoff timer until 2024-11-18T22:01:57.983Z
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> IDLE
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:01:57.591Z)"
D 2024-11-18T22:01:57.591Z | v1.12.2 1087900 | resolving_load_balancer | requestReresolution delayed by backoff timer until 2024-11-18T22:01:57.983Z
D 2024-11-18T22:01:57.592Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.592Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:01:57.592Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.472Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> CONNECTING
D 2024-11-18T22:02:01.472Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:02:01.472Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:02:01.472Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:02:01.472Z)"
D 2024-11-18T22:02:01.472Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> IDLE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 connection failed with error connect ECONNREFUSED 127.0.0.1:5999
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> TRANSIENT_FAILURE with error "connect ECONNREFUSED 127.0.0.1:5999 (2024-11-18T22:02:01.473Z)"
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | resolving_load_balancer | requestReresolution delayed by backoff timer until 2024-11-18T22:02:08.078Z
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:01.473Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> TRANSIENT_FAILURE
D 2024-11-18T22:02:13.686Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 TRANSIENT_FAILURE -> CONNECTING
D 2024-11-18T22:02:13.686Z | v1.12.2 1087900 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:02:13.686Z | v1.12.2 1087900 | subchannel | (2) 127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:02:13.686Z | v1.12.2 1087900 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:02:13.686Z | v1.12.2 1087900 | subchannel_refcount | (2) 127.0.0.1:5999 refcount 2 -> 3
D 2024-11-18T22:02:13.687Z | v1.12.2 1087900 | subchannel_refcount | (2) 127.0.0.1:5999 refcount 3 -> 2
D 2024-11-18T22:02:13.687Z | v1.12.2 1087900 | pick_first | TRANSIENT_FAILURE -> READY
D 2024-11-18T22:02:13.687Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 TRANSIENT_FAILURE -> READY
D 2024-11-18T22:02:13.687Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 TRANSIENT_FAILURE -> READY
D 2024-11-18T22:02:13.687Z | v1.12.2 1087900 | transport | (2) 127.0.0.1:5999 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2024-11-18T22:02:18.408Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 READY -> READY
D 2024-11-18T22:02:18.408Z | v1.12.2 1087900 | connectivity_state | (2) dns:127.0.0.1:5999 READY -> READY

Then, i am restarting the server, and performing a third request, which is successful like the first one.

D 2024-11-18T22:02:24.669Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:02:24.669Z | v1.12.2 1087900 | connectivity_state | (3) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:02:24.669Z | v1.12.2 1087900 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:02:24.669Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | channel_stacktrace | (3) Channel constructed 
    at new InternalChannel (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (/home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
    at runNextTicks (node:internal/process/task_queues:60:5)
    at process.processTimers (node:internal/timers:516:9)
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 createResolvingCall [7] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] Created
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] Deadline: Infinity
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] start called
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | connectivity_state | (3) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] startRead called
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] write() called with message of length 23
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | resolving_call | [7] halfClose called
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | subchannel_refcount | (2) 127.0.0.1:5999 refcount 2 -> 3
D 2024-11-18T22:02:24.670Z | v1.12.2 1087900 | pick_first | IDLE -> READY
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | connectivity_state | (3) dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 createRetryingCall [8] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | resolving_call | [7] Created child [8]
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | retrying_call | [8] start called
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | channel | (3) dns:127.0.0.1:5999 createLoadBalancingCall [9] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | retrying_call | [8] Created child call [9] for attempt 1
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | load_balancing_call | [9] start called
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | load_balancing_call | [9] Pick called
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | load_balancing_call | [9] Pick result: COMPLETE subchannel: (2) 127.0.0.1:5999 status: undefined undefined
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | retrying_call | [8] startRead called
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | load_balancing_call | [9] startRead called
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | transport_flowctrl | (2) 127.0.0.1:5999 local window size: 65535 remote window size: 1048576
D 2024-11-18T22:02:24.671Z | v1.12.2 1087900 | transport_internals | (2) 127.0.0.1:5999 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | load_balancing_call | [9] Created child call [10]
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | retrying_call | [8] write() called with message of length 28
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | load_balancing_call | [9] write() called with message of length 28
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | subchannel_call | [10] write() called with message of length 28
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | subchannel_call | [10] sending data chunk of length 28
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | retrying_call | [8] halfClose called
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | load_balancing_call | [9] halfClose called
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | subchannel_call | [10] end() called
D 2024-11-18T22:02:24.672Z | v1.12.2 1087900 | subchannel_call | [10] calling end() on HTTP/2 stream
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | subchannel_call | [10] Received server headers:
                :status: 200
                content-type: application/grpc
                date: Mon, 18 Nov 2024 22:02:24 GMT

D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | load_balancing_call | [9] Received metadata
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | retrying_call | [8] Received metadata from child [9]
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | retrying_call | [8] Committing call [9] at index 0
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | resolving_call | [7] Received metadata
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | subchannel_call | [10] receive HTTP/2 data frame of length 131
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | subchannel_call | [10] parsed message of length 131
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | subchannel_call | [10] pushing to reader message of length 131
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | load_balancing_call | [9] Received message
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | retrying_call | [8] Received message from child [9]
D 2024-11-18T22:02:24.686Z | v1.12.2 1087900 | resolving_call | [7] Received message
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | resolving_call | [7] Finished filtering received message
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | subchannel_call | [10] Received server trailers:
                grpc-status: 0

D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | subchannel_call | [10] received status code 0 from server
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | subchannel_call | [10] ended with status: code=0 details=""
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | load_balancing_call | [9] Received status
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | load_balancing_call | [9] ended with status: code=0 details="" start time=2024-11-18T22:02:24.671Z
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | retrying_call | [8] Received status from child [9]
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | retrying_call | [8] state=COMMITTED handling status with progress PROCESSED from child [9] in state ACTIVE
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | retrying_call | [8] ended with status: code=0 details="" start time=2024-11-18T22:02:24.671Z
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | resolving_call | [7] Received status
D 2024-11-18T22:02:24.687Z | v1.12.2 1087900 | resolving_call | [7] ended with status: code=0 details=""
D 2024-11-18T22:02:24.688Z | v1.12.2 1087900 | subchannel_call | [10] HTTP/2 stream closed with code 0

Now let's see what is happening with Deno.

Here is the first successful request while server is running:

D 2024-11-18T22:05:31.354Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:05:31.354Z | v1.12.2 1090083 | connectivity_state | (1) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:05:31.354Z | v1.12.2 1090083 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:05:31.355Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:05:31.355Z | v1.12.2 1090083 | channel_stacktrace | (1) Channel constructed 
    at new InternalChannel (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
    at file:///home/rnzaou/ciron/grpc-bug/go.mjs:50:1
D 2024-11-18T22:05:31.356Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 createResolvingCall [0] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:05:31.356Z | v1.12.2 1090083 | resolving_call | [0] Created
D 2024-11-18T22:05:31.356Z | v1.12.2 1090083 | resolving_call | [0] Deadline: Infinity
D 2024-11-18T22:05:31.356Z | v1.12.2 1090083 | resolving_call | [0] start called
D 2024-11-18T22:05:31.357Z | v1.12.2 1090083 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:05:31.357Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:05:31.357Z | v1.12.2 1090083 | connectivity_state | (1) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:05:31.357Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:05:31.357Z | v1.12.2 1090083 | resolving_call | [0] startRead called
D 2024-11-18T22:05:31.358Z | v1.12.2 1090083 | resolving_call | [0] write() called with message of length 23
D 2024-11-18T22:05:31.358Z | v1.12.2 1090083 | resolving_call | [0] halfClose called
D 2024-11-18T22:05:31.359Z | v1.12.2 1090083 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:05:31.359Z | v1.12.2 1090083 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | subchannel | (1) 127.0.0.1:5999 Subchannel constructed with options {}
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 0 -> 1
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 1 -> 2
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | pick_first | Start connecting to subchannel with address 127.0.0.1:5999
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | pick_first | IDLE -> CONNECTING
D 2024-11-18T22:05:31.360Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:05:31.361Z | v1.12.2 1090083 | connectivity_state | (1) dns:127.0.0.1:5999 CONNECTING -> CONNECTING
D 2024-11-18T22:05:31.361Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:05:31.361Z | v1.12.2 1090083 | subchannel | (1) 127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:05:31.362Z | v1.12.2 1090083 | transport | dns:127.0.0.1:5999 creating HTTP/2 session to 127.0.0.1:5999
D 2024-11-18T22:05:31.363Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 createRetryingCall [1] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:05:31.363Z | v1.12.2 1090083 | resolving_call | [0] Created child [1]
D 2024-11-18T22:05:31.363Z | v1.12.2 1090083 | retrying_call | [1] start called
D 2024-11-18T22:05:31.363Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 createLoadBalancingCall [2] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:05:31.363Z | v1.12.2 1090083 | retrying_call | [1] Created child call [2] for attempt 1
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | load_balancing_call | [2] start called
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | load_balancing_call | [2] Pick called
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | load_balancing_call | [2] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | retrying_call | [1] startRead called
D 2024-11-18T22:05:31.364Z | v1.12.2 1090083 | load_balancing_call | [2] startRead called
D 2024-11-18T22:05:31.365Z | v1.12.2 1090083 | retrying_call | [1] write() called with message of length 28
D 2024-11-18T22:05:31.365Z | v1.12.2 1090083 | load_balancing_call | [2] write() called with message of length 28
D 2024-11-18T22:05:31.365Z | v1.12.2 1090083 | retrying_call | [1] halfClose called
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | subchannel | (1) 127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 2 -> 3
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 3 -> 2
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | pick_first | CONNECTING -> READY
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | channel | (1) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | load_balancing_call | [2] Pick called
D 2024-11-18T22:05:31.367Z | v1.12.2 1090083 | load_balancing_call | [2] Pick result: COMPLETE subchannel: (1) 127.0.0.1:5999 status: undefined undefined
D 2024-11-18T22:05:31.368Z | v1.12.2 1090083 | connectivity_state | (1) dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:05:31.368Z | v1.12.2 1090083 | transport_flowctrl | (1) 127.0.0.1:5999 local window size: undefined remote window size: undefined
D 2024-11-18T22:05:31.368Z | v1.12.2 1090083 | transport_internals | (1) 127.0.0.1:5999 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-11-18T22:05:31.369Z | v1.12.2 1090083 | load_balancing_call | [2] Created child call [3]
D 2024-11-18T22:05:31.369Z | v1.12.2 1090083 | subchannel_call | [3] write() called with message of length 28
D 2024-11-18T22:05:31.369Z | v1.12.2 1090083 | subchannel_call | [3] sending data chunk of length 28
D 2024-11-18T22:05:31.370Z | v1.12.2 1090083 | load_balancing_call | [2] halfClose called
D 2024-11-18T22:05:31.370Z | v1.12.2 1090083 | subchannel_call | [3] end() called
D 2024-11-18T22:05:31.370Z | v1.12.2 1090083 | subchannel_call | [3] calling end() on HTTP/2 stream
D 2024-11-18T22:05:31.383Z | v1.12.2 1090083 | subchannel_call | [3] Received server headers:
                :status: 200
                content-type: application/grpc
                date: Mon, 18 Nov 2024 22:05:31 GMT

D 2024-11-18T22:05:31.383Z | v1.12.2 1090083 | load_balancing_call | [2] Received metadata
D 2024-11-18T22:05:31.384Z | v1.12.2 1090083 | retrying_call | [1] Received metadata from child [2]
D 2024-11-18T22:05:31.384Z | v1.12.2 1090083 | retrying_call | [1] Committing call [2] at index 0
D 2024-11-18T22:05:31.384Z | v1.12.2 1090083 | resolving_call | [0] Received metadata
D 2024-11-18T22:05:31.384Z | v1.12.2 1090083 | subchannel_call | [3] receive HTTP/2 data frame of length 131
D 2024-11-18T22:05:31.384Z | v1.12.2 1090083 | subchannel_call | [3] parsed message of length 131
D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | subchannel_call | [3] pushing to reader message of length 131
D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | load_balancing_call | [2] Received message
D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | retrying_call | [1] Received message from child [2]
D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | resolving_call | [0] Received message
D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | subchannel_call | [3] Received server trailers:
                grpc-status: 0

D 2024-11-18T22:05:31.385Z | v1.12.2 1090083 | subchannel_call | [3] received status code 0 from server
D 2024-11-18T22:05:31.386Z | v1.12.2 1090083 | resolving_call | [0] Finished filtering received message
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | subchannel_call | [3] ended with status: code=0 details=""
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | load_balancing_call | [2] Received status
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | load_balancing_call | [2] ended with status: code=0 details="" start time=2024-11-18T22:05:31.363Z
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | retrying_call | [1] Received status from child [2]
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | retrying_call | [1] state=COMMITTED handling status with progress PROCESSED from child [2] in state ACTIVE
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | retrying_call | [1] ended with status: code=0 details="" start time=2024-11-18T22:05:31.363Z
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | resolving_call | [0] Received status
D 2024-11-18T22:05:31.388Z | v1.12.2 1090083 | resolving_call | [0] ended with status: code=0 details=""

Then i shut down the server, but there are no real time logs indicating that the connection has ended.

Then, for the second request:

D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | connectivity_state | (2) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | channel_stacktrace | (2) Channel constructed 
    at new InternalChannel (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
    at eventLoopTick (ext:core/01_core.js:214:9)
D 2024-11-18T22:06:02.669Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 createResolvingCall [4] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] Created
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] Deadline: Infinity
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] start called
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | connectivity_state | (2) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] startRead called
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] write() called with message of length 23
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | resolving_call | [4] halfClose called
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:06:02.670Z | v1.12.2 1090083 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 2 -> 3
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | pick_first | IDLE -> READY
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | connectivity_state | (2) dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 createRetryingCall [5] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | resolving_call | [4] Created child [5]
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | retrying_call | [5] start called
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | channel | (2) dns:127.0.0.1:5999 createLoadBalancingCall [6] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | retrying_call | [5] Created child call [6] for attempt 1
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | load_balancing_call | [6] start called
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | load_balancing_call | [6] Pick called
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | load_balancing_call | [6] Pick result: COMPLETE subchannel: (1) 127.0.0.1:5999 status: undefined undefined
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | retrying_call | [5] startRead called
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | load_balancing_call | [6] startRead called
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | transport_flowctrl | (1) 127.0.0.1:5999 local window size: undefined remote window size: undefined
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | transport_internals | (1) 127.0.0.1:5999 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-11-18T22:06:02.671Z | v1.12.2 1090083 | load_balancing_call | [6] Created child call [7]
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | retrying_call | [5] write() called with message of length 28
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | load_balancing_call | [6] write() called with message of length 28
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | subchannel_call | [7] write() called with message of length 28
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | subchannel_call | [7] sending data chunk of length 28
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | retrying_call | [5] halfClose called
D 2024-11-18T22:06:02.673Z | v1.12.2 1090083 | subchannel_call | [7] Node error event: message=connection closed because of a broken pipe code=undefined errno=Unknown system error undefined syscall=undefined
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | subchannel_call | [7] HTTP/2 stream closed with code 2
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | subchannel_call | [7] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe"
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | load_balancing_call | [6] Received status
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | load_balancing_call | [6] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe" start time=2024-11-18T22:06:02.671Z
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | retrying_call | [5] Received status from child [6]
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | retrying_call | [5] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [6] in state ACTIVE
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | retrying_call | [5] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe" start time=2024-11-18T22:06:02.671Z
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | resolving_call | [4] Received status
D 2024-11-18T22:06:02.674Z | v1.12.2 1090083 | resolving_call | [4] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe"
13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe

I restart the server, and then the final request still fails with the broken pipe error:

D 2024-11-18T22:06:33.899Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:06:33.899Z | v1.12.2 1090083 | connectivity_state | (3) dns:127.0.0.1:5999 IDLE -> IDLE
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | dns_resolver | Resolver constructed for target dns:127.0.0.1:5999
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 Channel constructed with options {}
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | channel_stacktrace | (3) Channel constructed 
    at new InternalChannel (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/internal-channel.js:262:23)
    at new ChannelImplementation (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/client.js:66:36)
    at new ServiceClientImpl (file:///home/rnzaou/ciron/grpc-bug/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at go (file:///home/rnzaou/ciron/grpc-bug/go.mjs:12:22)
    at eventLoopTick (ext:core/01_core.js:214:9)
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 createResolvingCall [8] method="/ciron.server.tokens.TokensService/PasswordAuthenticate", deadline=Infinity
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] Created
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] Deadline: Infinity
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] start called
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | dns_resolver | Returning IP address for target dns:127.0.0.1:5999
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | connectivity_state | (3) dns:127.0.0.1:5999 IDLE -> CONNECTING
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] startRead called
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] write() called with message of length 23
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_call | [8] halfClose called
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | pick_first | updateAddressList([127.0.0.1:5999])
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | pick_first | connectToAddressList([127.0.0.1:5999])
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | pick_first | Pick subchannel with address 127.0.0.1:5999
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | subchannel_refcount | (1) 127.0.0.1:5999 refcount 3 -> 4
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | pick_first | IDLE -> READY
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | resolving_load_balancer | dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | connectivity_state | (3) dns:127.0.0.1:5999 CONNECTING -> READY
D 2024-11-18T22:06:33.900Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 createRetryingCall [9] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | resolving_call | [8] Created child [9]
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | retrying_call | [9] start called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | channel | (3) dns:127.0.0.1:5999 createLoadBalancingCall [10] method="/ciron.server.tokens.TokensService/PasswordAuthenticate"
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | retrying_call | [9] Created child call [10] for attempt 1
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] start called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] Pick called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] Pick result: COMPLETE subchannel: (1) 127.0.0.1:5999 status: undefined undefined
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | retrying_call | [9] startRead called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] startRead called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | transport_flowctrl | (1) 127.0.0.1:5999 local window size: undefined remote window size: undefined
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | transport_internals | (1) 127.0.0.1:5999 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] Created child call [11]
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | retrying_call | [9] write() called with message of length 28
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | load_balancing_call | [10] write() called with message of length 28
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | subchannel_call | [11] write() called with message of length 28
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | subchannel_call | [11] sending data chunk of length 28
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | retrying_call | [9] halfClose called
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | subchannel_call | [11] Node error event: message=connection closed because of a broken pipe code=undefined errno=Unknown system error undefined syscall=undefined
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | subchannel_call | [11] HTTP/2 stream closed with code 2
D 2024-11-18T22:06:33.901Z | v1.12.2 1090083 | subchannel_call | [11] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe"
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | load_balancing_call | [10] Received status
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | load_balancing_call | [10] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe" start time=2024-11-18T22:06:33.901Z
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | retrying_call | [9] Received status from child [10]
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | retrying_call | [9] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [10] in state ACTIVE
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | retrying_call | [9] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe" start time=2024-11-18T22:06:33.901Z
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | resolving_call | [8] Received status
D 2024-11-18T22:06:33.902Z | v1.12.2 1090083 | resolving_call | [8] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe"
13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: connection closed because of a broken pipe
murgatroid99 commented 1 week ago

The gRPC client primarily relies on two behaviors in Node to detect that a connection has closed:

  1. When a connection closes, the goaway and/or close events fire
  2. If a connection is already closed, attempting to start a new stream on it throws an error synchronously (to handle the case where the events don't fire)

According to the log, Deno is not doing either of these things, so the gRPC client never knows that the connection has become unusable. This is a Deno bug; it needs to notify HTTP2 session users that connections have closed.

As a side note, the logs show that you are creating a new client for every request. We recommend the opposite: that you use a single client to make all of your requests to the same service.

rnza0u commented 1 week ago

Thanks for the analysis and for your piece of advice...

I already made a tick to the Deno team here https://github.com/denoland/deno/issues/26907.