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.

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

RST_STREAM with code 2 / system error -505 when using HTTP CONNECT proxy #2744

Open
mjameswh opened this issue May 9, 2024 · 6 comments · May be fixed by #2746
Open

RST_STREAM with code 2 / system error -505 when using HTTP CONNECT proxy #2744

mjameswh opened this issue May 9, 2024 · 6 comments · May be fixed by #2746

Comments

@mjameswh
Copy link

mjameswh commented May 9, 2024

Problem description

When using an HTTP CONNECT proxy, it is possible for the server's first HTTP2 packet to reach the client before the latter sends its own first HTTP2 packet. If that happens, then the client terminates the connection (HTTP2 GOAWAY with code 2 and system error -505) and fail. Other gRPC implementations that we tested (Go, Java, and the Tokio third party implementation in Rust) don't have issue in that same scenario.

For example, in the capture below, we can see the server's first packet, at line 19, while the client's first packet, including the HTTP2 magic string is at line 21. Then, at line 37, we can see that the client side is initiating a GOAWAY, with code 2.

Screenshot 2024-05-08 at 13 20 20

With gRPC and node's tracing enabled, we can see the following interesting messages (this is a truncated snippet; see the attached zip file for the complete log and corresponding pcap).

Http2Session client (11473) Error 'Remote peer returned unexpected data while we expected SETTINGS frame.  Perhaps, peer does not support HTTP/2 properly.'
HttpStream 1 (11479) [Http2Session client (11473)] sending rst_stream with code 2
Http2Session client (11473) frame type 3 was not sent, code: -530
D 2024-05-09T18:52:34.462Z | v1.10.7 718 | subchannel_call | [571] Node error event: message=Protocol error code=ERR_HTTP2_ERROR errno=Unknown system error -505 syscall=undefined
D 2024-05-09T18:52:34.462Z | v1.10.7 718 | subchannel_call | [571] HTTP/2 stream closed with code 2
D 2024-05-09T18:52:34.462Z | v1.10.7 718 | subchannel_call | [571] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: Protocol error"

Reproduction steps

  1. Clone the repro from GitHub
git clone https://github.com/mjameswh/grpcjs-proxy-first-packet-repro.git
cd grpcjs-proxy-first-packet-repro
  1. Install npm dependencies.
$ npm i
  1. Start the gRPC server and proxy in background; alternatively, you may run these in a distinct tabs.
$ node src/greeter_server.js --port 6233 &
$ go run go/httpproxy.go --port 8888 &
  1. Run the client 1000 times, without proxy
$ node src/greeter_client.js --target 127.0.0.1:6233 --repeat 1000
Completed without error
  1. Run again, this time with proxy
$ export grpc_proxy=http://127.0.0.1:8888
$ node src/greeter_client.js --target 127.0.0.1:6233 --repeat 1000
Error: 13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: Protocol error
(**redacted for brievety; see full error details in linked gist**)
{
  code: 13,
  details: 'Received RST_STREAM with code 2 triggered by internal client error: Protocol error',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
Failed at iteration 43
  1. Restart the proxy, this time with the "wait for client's first packet" patch
$ killall  httpproxy
$ go run go/httpproxy.go --port 8888 --wait-for-first-client-packet &
  1. Run the client 1000 times, with the patched proxy
$ export grpc_proxy=http://127.0.0.1:8888
$ node src/greeter_client.js --target 127.0.0.1:6233 --repeat 1000

Environment

  • OS name: tested on MacOS 14.2.1 (Apple Silicon M2)
  • Node version: Node 20.12.2
  • Node installation method: volta
  • Package name: @grpc/grpc-js v1.10.7

Additional context

I only have limited knowledge of the HTTP2 protocol internals, but as far as I understand, though unlikely, the fact that the server's first packet reaches the client before the client its first packet is technically a legit situation, and could also happen in some non-proxied scenarios (e.g. using TCP Fast Open).

Therefore, this might arguably be IMHO an oversight in the underlying HTTP2 implementation, rather than a bug in grpc-node's proxy support; still, I'm reporting this here since I wouldn't be able to debate this further without considerably more digging of my part.

Attached files

@murgatroid99
Copy link
Member

It's hard to tell what exactly is going wrong here. It looks like the http2 client should be able to handle getting the settings frame early, but clearly it isn't here for some reason. One thing I noticed is that the log you supplied includes debug logs from the C++ part of the http2 implementation, but not the JavaScript part of the implementation. I'm not sure what would cause that, but it would have some relevant information.

One thing I want to note is that this problem shouldn't happen with TLS enabled, because that changes how the beginning of a connection is handled.

@mjameswh
Copy link
Author

One thing I noticed is that the log you supplied includes debug logs from the C++ part of the http2 implementation, but not the JavaScript part of the implementation. I'm not sure what would cause that, but it would have some relevant information.

If you mean the snippet that is visible in the ticket description, that log has been severely truncated, in the interest of making it easy to recognize other users searching for similar bugs in the future.

As for you, you will be more interested in the attached zip file, which includes the complete log 😉.

@murgatroid99
Copy link
Member

No, I'm talking about the log in the zip file. The Node http2 module has two major components: the C++ part that wraps nghttp2 and makes it interact with the Node runtime, and the JavaScript part that provides the public API. As far as I can tell, the log file you provided contains logs from the C++ part but not the JavaScript part. The clearest indication of this is that I see this line from the C++ part but not this line from the JavaScript part in the log. This is an issue because I would expect this other line from the JavaScript part to be a relevant indicator for this problem.

I haven't dug into Node's built in debug logging, so I don't know what exactly would cause this discrepancy.

@mjameswh
Copy link
Author

One thing I want to note is that this problem shouldn't happen with TLS enabled, because that changes how the beginning of a connection is handled.

Yeah, I assumed that much.

By the way, this is not a blocker on our side. For testing purpose, patching the simple proxy server is enough, and for production use cases, I expect everyone would TLS the HTTP2/gRPC connection. I shared my findings mainly because I had already done the investigation that far, and at that point, it is easily reproducible, contrarily to most other cases of RST_STREAM/code 2 errors. But no pressure.

@mjameswh
Copy link
Author

I was missing http2 in NODE_DEBUG.

Now, I can see HTTP2 80779: Http2Session client: created, but still no bytes already in buffer. Here's the new log file: trace.log. Search for the last ===== separator to get to the failing attempt.

Here's the command I'm using. Any flag/option I should turn on?

GRPC_VERBOSITY=DEBUG GRPC_TRACE=all NODE_DEBUG_NATIVE=HTTP2SESSION,HTTP2STREAM NODE_DEBUG=http,net,http2 grpc_proxy=http://127.0.0.1:8888 node src/greeter_client.js --target 127.0.0.1:6233 --repeat 1000 &> trace.log

@mjameswh
Copy link
Author

I got it. The problem is that node's HTTP response parser may take multiple packets ahead while filling its parsing buffer. This is exactly what happens if the server's first HTTP2 packet comes in before node is done parsing the Http/1.1 200 Connected response. Note the comment for the head argument to the HTTP.connect event.

This works locally.

@mjameswh mjameswh linked a pull request May 14, 2024 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants