After client's RST_STREAM, headers from the server cause client to tear down connection #1799
Description
An http2 transport connection can be inappropriately forcefully terminated in the following scenario:
- The client opens a stream—say, stream id 3—and sends a message to the server.
- After some time, the client wants to cancel its request, so it terminates the stream. This sends an
RST_STREAMheader to the server and removes stream id 3 from its_openStreamsmap. - At the same time, the server completes its response, so sends a
HeadersFramealong the connection with stream id 3. - The client processes the incoming headers frame, and sees that
_openStreams[streamId]does not currently exist. It assumes that the server is trying to open a new stream, and throws a protocol exception: "HTTP/2 clients cannot receive HEADER_FRAMEs as a connection attempt". - This is caught by
_catchProtocolErrors, which causes the entire connection to be torn down with "Connection is being forcefully terminated." This interrupts any other streams, which may have unrelated, long-running calls.
The HTTP/2 spec (RFC 7540, §5.4.2 Stream Error Handling) says:
A
RST_STREAMis the last frame that an endpoint can send on a stream. The peer that sends theRST_STREAMframe MUST be prepared to receive any frames that were sent or enqueued for sending by the remote peer. These frames can be ignored, except where they modify connection state (such as the state maintained for header compression […] or flow control).
The Dart http2 client is not following this spec. When it receives these frames that were sent by the remote peer, it does not ignore them. Instead, it causes unrelated streams to crash.
I'm hitting this in the real world with the following gRPC setup:
- A gRPC server, written in Go, tries to do some work, but aborts early if its client context is cancelled.
- A Dart gRPC client calls the method with a short deadline in a loop.
- Sometimes, we hit this case: the client timeout fires and cancels the stream, but the server
DEADLINE_EXCEEDEDresponse is already in flight, and so the transport is destroyed, interrupting any subsequent call that may have already started, or any concurrent call that may have been in progress.
(The go-grpc server behavior changed here somewhat in v1.72.0 in a way that makes this a bit less likely to hit. But it's still possible, since the server fix is nondeterministic and network delays still exist.)
I do have a repro setup based on the gRPC example servers, and though it's not super slimmed down, I can present some logs that are pretty clear:
1 [1753404623.193611] making short call
2 [1753404623.193628] wctest: _cleanupClosedStream: removing streamId: 1
3 [1753404623.194071] wctest: stream_handler.dart: _sendHeaders: id=3; headers=[Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header']; endStream=false
4 [1753404623.194716] wctest: stream_handler: _endStream: id=3
5 [1753404623.194754] wctest: processing frame: Instance of 'WindowUpdateFrame'
6 [1753404623.194773] wctest: processing frame: Instance of 'PingFrame'
7 [1753404623.298960] wctest: streamQueueIn.onCancel.then callback for id=3
8 [1753404623.299194] wctest: _terminateStream: client writing RST_STREAM for id=3
9 [1753404623.299838] short-23: Caught error: gRPC Error (code: 4, codeName: DEADLINE_EXCEEDED, message: Deadline exceeded, details: null, rawResponse: null, trailers: {})
10 [1753404623.299918]
11 [1753404623.299954] making short call
12 [1753404623.299988] wctest: _cleanupClosedStream: removing streamId: 3
13 [1753404623.300853] wctest: stream_handler.dart: _sendHeaders: id=5; headers=[Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header', Instance of 'Header']; endStream=false
14 [1753404623.301582] wctest: stream_handler: _endStream: id=5
15 [1753404623.301644] wctest: processing frame: Instance of 'HeadersFrame'
16 [1753404623.301678] wctest: http2...stream_handler: _processStreamFrameInternal: frame is HeadersFrame; streamId=3; stream=null
17 [1753404623.302026] wctest: complaining about headers frame: stack: #0 StreamHandler._processStreamFrameInternal.<anonymous closure> (package:http2/src/streams/stream_handler.dart:557:81)
18 [1753404623.302079] #1 TerminatableMixin.ensureNotTerminatedSync (package:http2/src/error_handler.dart:31:13)
19 [1753404623.302112] #2 StreamHandler._processStreamFrameInternal (package:http2/src/streams/stream_handler.dart:523:12)
20 [1753404623.302146] #3 StreamHandler.processStreamFrame (package:http2/src/streams/stream_handler.dart:481:7)
21 [1753404623.302178] #4 Connection._handleFrameImpl (package:http2/src/connection.dart:373:16)
22 [1753404623.302209] #5 Connection._setupConnection.<anonymous closure>.<anonymous closure> (package:http2/src/connection.dart:167:16)
23 [1753404623.302242] #6 Connection._catchProtocolErrors (package:http2/src/connection.dart:304:9)
24 [1753404623.302275] #7 Connection._setupConnection.<anonymous closure> (package:http2/src/connection.dart:165:7)
25 [1753404623.302308] #8 _RootZone.runUnaryGuarded (dart:async/zone.dart:1778:10)
26 [1753404623.302341] #9 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:381:11)
27 [1753404623.302373] #10 _DelayedData.perform (dart:async/stream_impl.dart:573:14)
28 [1753404623.302403] #11 _PendingEvents.handleNext (dart:async/stream_impl.dart:678:11)
29 [1753404623.302433] #12 _PendingEvents.schedule.<anonymous closure> (dart:async/stream_impl.dart:649:7)
30 [1753404623.302462] #13 _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
31 [1753404623.302513] #14 _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
32 [1753404623.302563] #15 _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:127:13)
33 [1753404623.302597] #16 _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:194:5)
34 [1753404623.302628]
35 [1753404623.302661] _catchProtocolErrors got PROTOCOL_ERROR: ProtocolError: HTTP/2 clients cannot receive HEADER_FRAMEs as a connectionattempt.
36 [1753404623.302961] wctest: forcefully terminating!!! stack trace: #0 Connection._terminate (package:http2/src/connection.dart:438:74)
37 [1753404623.303011] #1 Connection._catchProtocolErrors (package:http2/src/connection.dart:307:7)
38 [1753404623.303042] #2 Connection._setupConnection.<anonymous closure> (package:http2/src/connection.dart:165:7)
39 [1753404623.303072] #3 _RootZone.runUnaryGuarded (dart:async/zone.dart:1778:10)
40 [1753404623.303107] #4 _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:381:11)
41 [1753404623.303141] #5 _DelayedData.perform (dart:async/stream_impl.dart:573:14)
42 [1753404623.303171] #6 _PendingEvents.handleNext (dart:async/stream_impl.dart:678:11)
43 [1753404623.303203] #7 _PendingEvents.schedule.<anonymous closure> (dart:async/stream_impl.dart:649:7)
44 [1753404623.303236] #8 _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
45 [1753404623.303268] #9 _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
46 [1753404623.303300] #10 _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:127:13)
47 [1753404623.303331] #11 _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:194:5)
48 [1753404623.303363]
49 [1753404623.303398] wctest: _cleanupClosedStream: removing streamId: 5
50 [1753404623.303745] short-24: Caught error: gRPC Error (code: 2, codeName: UNKNOWN, message: HTTP/2 error: Connection error: Connection is being forcefully terminated. (errorCode: 1), details: null, rawResponse: null, trailers: {})
51 [1753404623.303797]
52 [1753404623.303830] making short call
53 [1753404623.303953] changed! ConnectionState.idle
54 [1753404623.304003] changed! ConnectionState.connecting
The key bits are:
- line 8, at 299ms: client sends RST_STREAM for stream id 3
- line 12, at 299ms: client removes stream id 3 from its internal data structures, forgetting about it
- line 16, at 301ms: client receives first response frame from server for stream id 3
- line 17, at 302ms: client panics because it's a protocol error to "receive HEADER_FRAMEs as a connectionattempt", and so the client escalates to forcefully terminate the whole connection
- line 50, at 303ms: other calls on the gRPC connection are interrupted and abruptly terminated
- line 54, at 303ms: future calls on the gRPC connection see the HTTP/2 connection rebuilt
To run this repro yourself, you can grab this Dockerfile:
https://gist.github.com/wchargin/9934394d50185f62e49188d2268da937
…then run it with:
$ docker build -t dart-http2-rst-stream-issue .
$ docker run --rm -it dart-http2-rst-stream-issueYou should be able to see a forceful termination within 10 seconds or so of the client logs starting to run.