Intermittently the client enters a state where it doesnt receive response sent by server
- Dominant language
- TypeScript
- Stars
- 4.8k
- Forks
- 716
- Avg merge
- 2d 3h
- Merged PRs (30d)
- 10
Description
### Problem description
Intermittently our grpc client is entering a state where the server is sending a response to the client, but the client doesnt receive it and throws a DEADLINE_EXCEEDED error. The error persists on retries until the server or client is restarted.
### Reproduction steps
Unknown - appears to eventually enter this state in longer lived environments.
### Environment
- OS name, version and architecture: Alpine
- Node version: 18
- Package name and version: grpc-js 1.8.14
### Additional context
Client Logs
```
D 2023-07-12T20:00:37.761Z | resolving_call | [4] Created
D 2023-07-12T20:00:37.761Z | channel | (43) dns:createResolvingCall [4] method=“”, deadline=2023-07-12T20:01:22.760Z
D 2023-07-12T20:00:37.762Z | resolving_call | [4] start called
D 2023-07-12T20:00:37.762Z | resolving_call | [4] Deadline will be reached in 44998ms
D 2023-07-12T20:00:37.762Z | resolving_call | [4] Deadline: 2023-07-12T20:01:22.760Z
D 2023-07-12T20:00:37.763Z | resolving_call | [4] startRead called
D 2023-07-12T20:00:37.764Z | resolving_call | [4] halfClose called
D 2023-07-12T20:00:37.764Z | resolving_call | [4] write() called with message of length 38
D 2023-07-12T20:00:37.764Z | resolving_call | [4] Created child [5]
D 2023-07-12T20:00:37.764Z | channel | (43) dns: createRetryingCall [5] method=""
D 2023-07-12T20:00:37.765Z | load_balancing_call | [6] start called
D 2023-07-12T20:00:37.765Z | retrying_call | [5] Created child call [6] for attempt 1
D 2023-07-12T20:00:37.765Z | channel | (43) dns: createLoadBalancingCall [6] method=""
D 2023-07-12T20:00:37.765Z | retrying_call | [5] start called
D 2023-07-12T20:00:37.766Z | load_balancing_call | [6] Pick called
D 2023-07-12T20:00:37.766Z | load_balancing_call | [6] Pick result: COMPLETE subchannel: (44) status: undefined undefined
D 2023-07-12T20:00:37.766Z | retrying_call | [5] startRead called
D 2023-07-12T20:00:37.770Z | load_balancing_call | [6] Created child call [7]
D 2023-07-12T20:00:37.770Z | transport_internals | (45) session.closed=false session.destroyed=false session.socket.destroyed=false
D 2023-07-12T20:00:37.770Z | transport_flowctrl | (45) local window size: 65535 remote window size: 65535
D 2023-07-12T20:00:37.771Z | retrying_call | [5] write() called with message of length 43
D 2023-07-12T20:00:37.771Z | subchannel_call | [7] sending data chunk of length 43
D 2023-07-12T20:00:37.771Z | subchannel_call | [7] write() called with message of length 43
D 2023-07-12T20:00:37.771Z | load_balancing_call | [6] write() called with message of length 43
D 2023-07-12T20:00:37.772Z | retrying_call | [5] halfClose called
D 2023-07-12T20:00:37.773Z | subchannel_call | [7] calling end() on HTTP/2 stream
D 2023-07-12T20:00:37.773Z | subchannel_call | [7] end() called
D 2023-07-12T20:00:37.773Z | load_balancing_call | [6] halfClose called
D 2023-07-12T20:01:22.760Z | resolving_call | [4] cancelWithStatus code: 4 details: "Deadline exceeded"
D 2023-07-12T20:01:22.760Z | retrying_call | [5] cancelWithStatus code: 4 details: "Deadline exceeded"
D 2023-07-12T20:01:22.761Z | retrying_call | [5] ended with status: code=4 details="Deadline exceeded"
D 2023-07-12T20:01:22.761Z | load_balancing_call | [6] cancelWithStatus code: 4 details: "Deadline exceeded"
D 2023-07-12T20:01:22.761Z | subchannel_call | [7] cancelWithStatus code: 4 details: "Deadline exceeded"
D 2023-07-12T20:01:22.761Z | subchannel_call | [7] ended with status: code=4 details="Deadline exceeded"
D 2023-07-12T20:01:22.762Z | retrying_call | [5] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [6] in state ACTIVE
D 2023-07-12T20:01:22.762Z | retrying_call | [5] Received status from child [6]
D 2023-07-12T20:01:22.762Z | load_balancing_call | [6] ended with status: code=4 details="Deadline exceeded"
D 2023-07-12T20:01:22.762Z | subchannel_call | [7] close http2 stream with code 8
D 2023-07-12T20:01:22.763Z | resolving_call | [4] Received status
D 2023-07-12T20:01:22.763Z | load_balancing_call | [6] Received status
D 2023-07-12T20:01:22.763Z | resolving_call | [4] Received status
D 2023-07-12T20:01:22.763Z | resolving_call | [4] ended with status: code=4 details="Deadline exceeded"
D 2023-07-12T20:01:22.763Z | retrying_call | [5] ended with status: code=4 details="Deadline exceeded"
D 2023-07-12T20:01:22.864Z | subchannel_call | [7] HTTP/2 stream closed with code 8
```
Server Logs
```
D 2023-07-12T20:00:37.774Z | server | (1) Received call to method at address null
D 2023-07-12T20:00:37.774Z | server_call | Request to received headers {"trackingid”:[“”],”grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"grpc-timeout":["44993m"],"user-agent":["grpc-node-js/1.8.14"],"content-type":["application/grpc"],"te":["trailers"]}
D 2023-07-12T20:00:37.777Z | server_call | Request to method stream closed with rstCode 0
D 2023-07-12T20:00:37.777Z | server_call | Request to method ended with status code: OK details: OK
```
As you can see the server responds well within the deadline but the client never gets the response. I know transient failures can happen but since it persists on retries it appears there is something deeper going on here.
Contributor guide
Assessment
This issue has not been assessed yet.