search

python-hyper / h2

HTTP/2 State-Machine based protocol implementation
https://h2.readthedocs.io/en/stable
MIT License
963 stars 151 forks source link

StreamClosedError on receiving WINDOW_UPDATE on a stream in a "closed" state #1205

Closed seleznevae closed 4 years ago

seleznevae commented 4 years ago

Hi! I am writing http2 client on c++ using libnghttp2 and test it with server written on python and use hyper-h2 for the server (hyper-h2 version is v3.1.1).

I've encountered an error when hyper-h2 generates StreamClosedError on receiving WINDOW_UPDATE for a stream that is in closed stated. This problem seems similar to https://github.com/python-hyper/hyper-h2/issues/1183 but it is not quite the same.

Short description of the timeline from client's point of view:

> Client initiates connection and makes request (stream_id = 1)
< Client receives response
> Client tries to do 3 requests simultaneously (streams_id = 3, 5, 7)
< Client receives part of the response for stream_id 3
> Client sends WINDOW_UPDATE for connection (stream_id = 0) and for stream_id = 3
< Client receives rest of the response for stream_id 3
< Client receives part of the response for stream_id 5
< Client receives GOAWAY

Short description of the timeline from server's point of view:

> Server accepts connection and receives request (stream_id = 1)
< Server replies to stream_id = 1 (stream_id = 1 is in closed state)
> Server receives request (stream_id = 3)
> Server receives request (stream_id = 5)
< Server sends first part of the reply for stream_id = 3
< Server sends rest of the reply for stream_id = 3 (stream_id == 3 is now in 'closed' state)
< Server sends first part of reply (stream_id = 5) (window is to small to send all data)
> Server receives request (stream_id = 7) (at this point closed stream with id == 3 is moved from container that holds streams to '_closed_streams' container)
> Server receives WINDOW_UPDATE for connection (stream_id == 0)
> Server receives WINDOW_UPDATE for connection (stream_id == 3). At this point '_get_stream_by_id' fails because it can't find stream with id == 3 (this stream is now in container 'Connection._closed_streams' of the connection) and StreamClosedError is generated.
< Server sends GOAWAY and closes connection

So the main problem is that stream with id == 3 is closed by h2. Then after receiving another request this closed stream is moved to Connection._closed_streams. And when WINDOW_UPDATE for id == 3 arrives, hyper-h2 cannot find stream with such id.

Here are more detailed logs of the server (Logs from hyper-h2 code itself have tag [hyper-h2]. Also I logged states of Connection._closed_streams and Connection.streams when an error occurred):

Starting http2 server
Starting http2 server
H2Protocol __init__
connection_made

data_received: size = 76
[hyper-h2] [_receive_settings_frame]; id = 0
[hyper-h2] [_receive_headers_frame] stream_id = 1
 RemoteSettingsChanged event
 RequestReceived event; stream_id = 1
 StreamEnded event; stream_id = 1
  send_data; stream_id = 1; data_to_send = 491
   remained_to_send = 491; local_flow_control_window = 65535
    self.conn.send_data chunksize = 491; stream_id = 1

data_received: size = 9
[hyper-h2] [_receive_settings_frame]; id = 0

data_received: size = 75
[hyper-h2] [_receive_headers_frame] stream_id = 3
[hyper-h2] [_open_streams] pop stream_id =1 (moving it to self._closed_streams)
[hyper-h2] [_receive_headers_frame] stream_id = 5
 RequestReceived event; stream_id = 3
 StreamEnded event; stream_id = 3
 RequestReceived event; stream_id = 5
 StreamEnded event; stream_id = 5
  send_data; stream_id = 3; data_to_send = 32769
   remained_to_send = 32769; local_flow_control_window = 65044
    self.conn.send_data chunksize = 16384; stream_id = 3
   remained_to_send = 16385; local_flow_control_window = 48660
    self.conn.send_data chunksize = 16384; stream_id = 3
   remained_to_send = 1; local_flow_control_window = 32276
    self.conn.send_data chunksize = 1; stream_id = 3
  send_data; stream_id = 5; data_to_send = 32769
   remained_to_send = 32769; local_flow_control_window = 32275
    self.conn.send_data chunksize = 16384; stream_id = 5
   remained_to_send = 16385; local_flow_control_window = 15891
    self.conn.send_data chunksize = 15891; stream_id = 5
   remained_to_send = 494; local_flow_control_window = 0
    wait_for_flow_control; stream_id = 5

data_received: size = 36
[hyper-h2] [_receive_headers_frame] stream_id = 7
[hyper-h2] [_open_streams] pop stream_id =3 (moving it to self._closed_streams)
 RequestReceived event; stream_id = 7
 StreamEnded event; stream_id = 7
  send_data; stream_id = 7; data_to_send = 32769
   remained_to_send = 32769; local_flow_control_window = 0
    wait_for_flow_control; stream_id = 7

data_received: size = 13
[hyper-h2] [_receive_window_update_frame] stream_id = 0; window_increment = 33250
 WindowUpdated event; stream_id = 0; delta = 33250

data_received: size = 13
[hyper-h2] [_receive_window_update_frame] stream_id = 3; window_increment = 32768
[hyper-h2] [_get_stream_by_id] failed to find stream_id =3
     self.streams = {5: <H2Stream id:5 state:<StreamState.HALF_CLOSED_REMOTE: 4>>, 7: <H2Stream id:7 state:<StreamState.HALF_CLOSED_REMOTE: 4>>}
     self._closed_streams = SizeLimitDict([(1, <StreamClosedBy.SEND_END_STREAM: 0>), (3, <StreamClosedBy.SEND_END_STREAM: 0>)])
StreamClosedError; error_code = 5; stream_id = 3
Closing transport
  wait_for_flow_control END; stream_id = 5
    self.conn.send_data chunksize = 494; stream_id = 5
  wait_for_flow_control END; stream_id = 7
    self.conn.send_data chunksize = 16384; stream_id = 7
connection_lost

And here logs of the client:

 13:49:16.560  INFO: [http2] Send Frame Callback: frame HTTP2_SETTINGS(streamId:0)(length:12)(flags:None)
 13:49:16.560  INFO: [http2] Http2Stream constructor
 13:49:16.560  INFO: [http2] Submit request; streamId = 1
 13:49:16.561  INFO: [http2] Send Frame Callback: frame HTTP2_HEADERS(streamId:1)(length:22)(flags:|END_STREAM|END_HEADERS|ACK)
 13:49:16.561  INFO: [http2] Recv Frame Callback: frame HTTP2_SETTINGS(streamId:0)(length:42)(flags:None)
 13:49:16.561  INFO: [http2] Send Frame Callback: frame HTTP2_SETTINGS(streamId:0)(length:0)(flags:|END_STREAM|ACK)
 13:49:16.562  INFO: [http2] Recv Frame Callback: frame HTTP2_SETTINGS(streamId:0)(length:0)(flags:|END_STREAM|ACK)
 13:49:16.563  INFO: [http2] Recv Frame Callback: frame HTTP2_HEADERS(streamId:1)(length:32)(flags:|END_HEADERS)
 13:49:16.563  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:1)(length:491)(flags:|END_STREAM|ACK)
 13:49:16.563  INFO: [http2] Close Stream Callback streamId = 1; errorCode = 0
 13:49:16.563  INFO: [http2] ~Http2Stream() destructor (streamId = 1)(errors:no errors)
 13:49:16.571  INFO: [http2] Submit request; streamId = 3
 13:49:16.571  INFO: [http2] Send Frame Callback: frame HTTP2_HEADERS(streamId:3)(length:30)(flags:|END_STREAM|END_HEADERS|ACK)
 13:49:16.572  INFO: [http2] Submit request; streamId = 5
 13:49:16.572  INFO: [http2] Send Frame Callback: frame HTTP2_HEADERS(streamId:5)(length:27)(flags:|END_STREAM|END_HEADERS|ACK)
 13:49:16.572  INFO: [http2] Submit request; streamId = 7
 13:49:16.572  INFO: [http2] Send Frame Callback: frame HTTP2_HEADERS(streamId:7)(length:27)(flags:|END_STREAM|END_HEADERS|ACK)
 13:49:16.574  INFO: [http2] Recv Frame Callback: frame HTTP2_HEADERS(streamId:3)(length:9)(flags:|END_HEADERS)
 13:49:16.574  INFO: [http2] Recv Frame Callback: frame HTTP2_HEADERS(streamId:5)(length:4)(flags:|END_HEADERS)
 13:49:16.575  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:3)(length:16384)(flags:None)
 13:49:16.575  INFO: [http2] Send Frame Callback: frame HTTP2_WINDOW_UPDATE(window_size_increment:33250)(streamId:0)(length:4)(flags:None)
 13:49:16.576  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:3)(length:16384)(flags:None)
 13:49:16.576  INFO: [http2] Send Frame Callback: frame HTTP2_WINDOW_UPDATE(window_size_increment:32768)(streamId:3)(length:4)(flags:None)
 13:49:16.576  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:3)(length:1)(flags:|END_STREAM|ACK)
 13:49:16.576  INFO: [http2] Close Stream Callback streamId = 3; errorCode = 0
 13:49:16.576  INFO: [http2] ~Http2Stream() destructor (streamId = 3)(errors:no errors)
 13:49:16.577  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:5)(length:16384)(flags:None)
 13:49:16.577  INFO: [http2] Recv Frame Callback: frame HTTP2_DATA(streamId:5)(length:15891)(flags:None)
 13:49:16.577  INFO: [http2] Recv Frame Callback: frame HTTP2_HEADERS(streamId:7)(length:4)(flags:|END_HEADERS)
 13:49:16.578  INFO: [http2] Recv Frame Callback: frame HTTP2_GOAWAY(error_code:5)(last_stream_id:7)(streamId:0)(length:8)(flags:None)
 13:49:16.578  INFO: [http2] terminateSession; error = GOAWAY_FRAME recieved
 13:49:16.578  INFO: [http2] ~Http2Stream() destructor (streamId = 7)(errors:GOAWAY_FRAME recieved)
 13:49:16.578  INFO: [http2] ~Http2Stream() destructor (streamId = 5)(errors:GOAWAY_FRAME recieved)

If more detailed logs for client or server are needed I can provide them.

pgjones commented 4 years ago

I think you are correct here for the same reasons in #1183. Thanks for the detailed logs I don't think I'd need anymore.

Kriechi commented 4 years ago

Since #1183 was fixed by a95556b, I'll mark this one a fixed as well.