`@grpc/grpc-js` throw 'Received RST_STREAM with code 0' with retry enabled

[nooop3]

Problem description

@grpc/grpc-js throw 'Received RST_STREAM with code 0' with retry enabled

Reproduction steps

• Start an example HelloWorld Golang grpc server in Kubernetes and enable the istio sidecar
• To reduce the connection reset(reset reason: connection termination), we set the max_concurrent_streams: 256
• Making multi-calls same time by nodeJs with large responses (like response size 6k/per request, and 1000 requests)
• Got Error: 13 INTERNAL: Received RST_STREAM with code 0

Environment

• Kubernetes with istio envoy sidecar enabled(Thanks orbstack Kubernetes environment, I can debug this error in local VSCode environment)
  • NodeJs -> client sidecar(envoy) -> server
  • NodeJs -> server sidecar(envoy) -> server
  • NodeJs -> client sidecar(envoy) -> server sidecar(envoy) -> server
• Node version: v16.18.1
• Node installation method: Docker image
• If applicable, compiler version: N/A
• Package name and version: @grpc/grpc-js version > 1.7.3

Additional context

Logs with GRPC_TRACE=all GRPC_VERBOSITY=DEBUG

D 2023-09-09T23:58:35.160Z | load_balancing_call | [1513] Received metadata
D 2023-09-09T23:58:35.160Z | retrying_call | [1512] Received metadata from child [1513]
D 2023-09-09T23:58:35.160Z | retrying_call | [1512] Committing call [1513] at index 0
D 2023-09-09T23:58:35.160Z | resolving_call | [256] Received metadata
D 2023-09-09T23:58:35.160Z | subchannel_call | [3256] HTTP/2 stream closed with code 0
D 2023-09-09T23:58:35.160Z | subchannel_call | [3256] ended with status: code=13 details="Received RST_STREAM with code 0"
D 2023-09-09T23:58:35.160Z | load_balancing_call | [1513] Received status
D 2023-09-09T23:58:35.160Z | load_balancing_call | [1513] ended with status: code=13 details="Received RST_STREAM with code 0"
D 2023-09-09T23:58:35.160Z | retrying_call | [1512] Received status from child [1513]
D 2023-09-09T23:58:35.160Z | retrying_call | [1512] state=COMMITTED handling status with progress PROCESSED from child [1513] in state ACTIVE
D 2023-09-09T23:58:35.160Z | retrying_call | [1512] ended with status: code=13 details="Received RST_STREAM with code 0"
D 2023-09-09T23:58:35.160Z | resolving_call | [256] Received status
D 2023-09-09T23:58:35.160Z | resolving_call | [256] ended with status: code=13 details="Received RST_STREAM with code 0"

Error: 13 INTERNAL: Received RST_STREAM with code 0
    at callErrorFromStatus (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/call.js:31:19)
    at Object.onReceiveStatus (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/client.js:192:76)
    at Object.onReceiveStatus (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:360:141)
    at Object.onReceiveStatus (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
    at /[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/resolving-call.js:94:78
    at processTicksAndRejections (node:internal/process/task_queues:78:11)
for call at
    at ServiceClientImpl.makeUnaryRequest (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/client.js:160:32)
    at ServiceClientImpl.<anonymous> (/[redacted]/grpc-node/examples/node_modules/@grpc/grpc-js/build/src/make-client.js:105:19)
    at /[redacted]/grpc-node/examples/helloworld/dynamic_codegen/client.js:73:14
    at new Promise (<anonymous>)
    at main (/[redacted]/grpc-node/examples/helloworld/dynamic_codegen/client.js:72:21)
    at Object.<anonymous> (/[redacted]/grpc-node/examples/helloworld/dynamic_codegen/client.js:102:1)
    at Module._compile (node:internal/modules/cjs/loader:1155:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1209:10)
    at Module.load (node:internal/modules/cjs/loader:1033:32)
    at Function.Module._load (node:internal/modules/cjs/loader:868:12) {
  code: 13,
  details: 'Received RST_STREAM with code 0',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}

Methods I can apply

• Disable grpc.enable_retries by set grpc.enable_retries = 0
• Downgrade to the version 1.7.3

It seems we can just ignore this error, and doesn't affect the results.
RST_STREAM with code NO_ERROR in HTTP2 RFC Error Codes

There are some similar cases in other projects:

• Issue 650438: Cronet treats RST_STREAM with code NO_ERROR as a SPDY failure (error -337)
• Issue 603182: RST_STREAM with NO_ERROR isn't handled properly
• HTTP/2: send WINDOW_UPDATE instead of RST_STREAM with NO_ERROR.
• HTTP/2: switched back to RST_STREAM with NO_ERROR.

So can we just ignore this NO_ERROR in the Node js SDK? Thanks in advance.

[nooop3]

In addition, the Golang client doesn't have this issue in the same environment.

[murgatroid99]

We have had similar reports before, and people who have experienced it have frequently reported that a configuration change fixed the problem. For example, #1532 (comment):

Please check your Istio Sidecar. In my case, the traffic to GRCP client was blocked by the Istio Sidecar.

After I disable the Istio Sidecar with annotation, it's working fine now.

#1532 (comment):

had the same issue (Error: 13 INTERNAL: Received RST_STREAM with code 0) but it turns out that the service I was calling was not accepting calls from outside the VPC, updated it to accept all traffic and issue was sorted.

#2004 (comment)

Enabling HTTP/2 end-to-end in my deployment settings on Cloud Run fixed the issue for me.

If you extend your log excerpt back a little further to a line that includes subchannel_call | [3256] Received server headers: I think we can get a better idea of what is happening here.

[nooop3]

Thanks for your reply. I had viewed those comments before:

We have had similar reports before, and people who have experienced it have frequently reported that a configuration change fixed the problem. For example, #1532 (comment):

Please check your Istio Sidecar. In my case, the traffic to GRCP client was blocked by the Istio Sidecar.
After I disable the Istio Sidecar with annotation, it's working fine now.

The traffic hasn't been blocked by Istio, the script works well if I disable the NodeJs grpc retry.
If I disable the Istio sidecar with the annotations, it's working fine either disable the grpc retry or not. But we need to use the Istio to load balance the grpc requests, so we need to enable the sidecar through the cluster.

#1532 (comment):

had the same issue (Error: 13 INTERNAL: Received RST_STREAM with code 0) but it turns out that the service I was calling was not accepting calls from outside the VPC, updated it to accept all traffic and issue was sorted.

I can reproduce this issue and debug with vscode in the local kubernetes by the orbstack. So the service can accept all traffic from out of the cluster.

#2004 (comment)

Enabling HTTP/2 end-to-end in my deployment settings on Cloud Run fixed the issue for me.

We are running the service in the EKS, and also can reproduce in the local kubernetes environment, we can not find any equal settings to enable the HTTP/2 end-to-end for Istio.

If you extend your log excerpt back a little further to a line that includes subchannel_call | [3256] Received server headers: I think we can get a better idea of what is happening here.

I'll upload more log tomorrow, and share the Wireshark screenshot.

[murgatroid99]

the script works well if I disable the NodeJs grpc retry

This part really confuses me. I can't think of anything in the retry code that would impact anything else that's happening in this issue. It might help to have more of the logs, back to the one that contains createRetryingCall [1512]. It might also help to have the logs from a call that is dropped for exceeding max_concurrent_streams with retries disabled, for comparison.

The traffic hasn't been blocked by Istio

If Istio is enforcing max_concurrent_streams, then this stream has been blocked by Istio, in the sense that it isn't forwarded to the server. If Istio is responding at the HTTP/2 protocol level instead of the gRPC protocol level, it wouldn't be surprising for it to respond in this way. Maybe there's a configuration to make its responses gRPC protocol-aware.

[nooop3]

There are logs:

Enable the reries:

grpc-rst-stream.log

Disable the retries

grpc-diable-retries.log

Can we just ignore the NO_ERROR when retry is enabled?

[murgatroid99]

Your two tests are doing different things. In the "Enable the retries" case, it makes 1000 requests, and in the "Disable the retries" case, it makes 512 requests. And there's nothing different in the response handling between the two logs, rather the second test just never receives the kind of response that triggers the error in the first test. I think the "Disable the retries" test just isn't running into the max concurrent streams limit.

The fact is that there is no reasonable way to handle this kind of response other than with an error. The client receives headers, which indicates that the server at least started to process the request, and the client treats that as a signal that the request can't be retried. And an RST_STREAM without a grpc-status trailer is considered a gRPC protocol error, which is why it's reported as an error. And even if we treated that as a success instead, the request would still fail at a higher layer because it never receives the response message it expects for that request.

[nooop3]

I reduced the request number to 512 as the log size was too large yesterday. And if I make 512 requests with retry enabled, this issue still exists:

grpc-rst-stream-512.log

To mitigate this issue, we have to pin the version of @grpc/grpc-js to 1.7.3.

[murgatroid99]

OK, I see what happened: having retries enabled changed the sequencing of some low-level operations, which caused a different outcome with your specific test setup. With retries disabled, each HTTP/2 stream starts and ends in a single synchronous operation, while with retries enabled, starting and ending the stream are separated into two asynchronous operations. The result is that with retries disabled, each stream starts and ends one at a time, while with retries enabled, all of the streams start, and then all of the streams end. This means that in the "retries disabled" case, the remote end can finish processing the first stream before the last stream even starts, while in the "retries enabled" case, the remote end is guaranteed to see all of the streams open at once. So, the primary difference between the observable outcomes in these two tests is that the "retries enabled" test triggers the "max concurrent streams" limit, and the "retries disabled" test does not. If you instead forced the client to reach the "max concurrent streams" limit by opening streaming requests without closing them, you would see the same error in both cases.

The primary problem here, still, is that when the "max concurrent streams" limit is reached, Istio closes the stream in a way that is not valid within the gRPC protocol. Istio is what needs to be changed here. There may be a configuration option to change how it responds in this situation, but if not, this is a bug in Istio.

[nooop3]

The max_concurrent_streams is the HTTP2 option that is included in the setting frame from the server(or Istio side). When the client receives the max_concurrent_streams setting, the client should follow this setting.
Is there any config we can set on the NodeJS side?

[murgatroid99]

That is a fair point. There should be client-side enforcement of the max concurrent streams limit, but as far as I know, there isn't.

[devpira]

Hello, we were also facing the exact issue with the same setup for some time now. After seeing this issue and pinning it to version 1.7.3, the errors have gone away. Ideally we don't want to keep it pinned 1.7.3. Just wanted to bring it up to see if there is anything that could be done? I can provide details if needed.

[murgatroid99]

Please share whatever details you have. They can only help understand the problem.

[murgatroid99]

I think it's possible that in this specific test scenario, the max concurrent streams setting may not be enforced on the client because all of the streams are started before the client receives the server's settings frame. That could be tested by making a request, and then once it succeeds synchronously making a number of requests greater than the max concurrent streams setting.

[maylorsan]

We've been facing this error in our production environment for the past 3 days and it's occurred roughly 15k times:
Error: 13 INTERNAL: Received RST_STREAM with code 1

The error is triggered when executing the following code:

const writeResult = await admin
      .firestore()
      .collection(FirestoreCollections.Users)
      .doc(userID)
      .update(fieldsToUpdate); // This line throws the error

We've attempted several methods, but none have resolved the problem:

• Switched the update method to use set and set with {merge: true}, but this didn't work.
• Created a new cloud function dedicated solely to this method. Surprisingly, it didn't work either. However, it's noteworthy that we have several other cloud functions that update user data using the same method, and they function as expected.
  What's even more perplexing is that this issue arises in about 60% of our http cloud function calls, and it seems to occur randomly. We haven't been able to identify a consistent pattern.

Interestingly, everything operates flawlessly in our development project. The only difference is that the development project has a smaller User collection.

@murgatroid99 Is any updates on this issue?
We using nodejs v16.20.0 and firebase-admin library