grpc / grpc/grpc-node

Intermittently the client enters a state where it doesnt receive response sent by server

Open
#2,502 30 comments 6 reactions 0 assignees View on GitHub
package: @grpc/grpc-js
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.