HTTP/2 5.1/5 is racy

[fraenkel]

I am getting the following failure:

    × 5: half closed (remote): Sends a DATA frame
        -> The endpoint MUST respond with a stream error of type STREAM_CLOSED.
           Expected: GOAWAY Frame (Error Code: STREAM_CLOSED)
                     RST_STREAM Frame (Error Code: STREAM_CLOSED)
                     Connection closed
             Actual: WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0)

My understanding is that WINDOW_UPDATE is allowed per 5.1 half-closed (local): In this state, a receiver can ignore WINDOW_UPDATE frames, which might arrive for a short period after a frame bearing the END_STREAM flag is sent.

[fraenkel]

On further review, there seems to be an expectation of how the server should behave with these requests. If the default behavior for a GET / is to return no data, many of the tests fail. The moment data is returned this test passes (mostly). The test is racy as are others. In this specific case, there is a race between the data frame from the HEADER request and the RST_STREAM from the data request. If I guarantee that I receive the response from the HEADER or delay the data request, it will always pass.

[fraenkel]

A similar issue occurs with http2/5.1/6.

It all comes down to when the second request appears on the Server, the stream may be in half-closed state or it may actually no longer exist because the response frame was already sent and therefore removed.

[summerwind]

May I have a verbose log with "--verbose" flag?

[fraenkel]

Here is the verbose for 5.1/5 and 5.1/6 which have similar issues. 5.1/5

           [send] SETTINGS Frame (length:6, flags:0x00, stream_id:0)
           [recv] SETTINGS Frame (length:24, flags:0x00, stream_id:0)
           [send] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
           [recv] WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0)
           [recv] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
           [send] HEADERS Frame (length:15, flags:0x05, stream_id:1)
           [send] DATA Frame (length:4, flags:0x01, stream_id:1)
           [recv] HEADERS Frame (length:49, flags:0x04, stream_id:1)
           [recv] WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0)
           [recv] DATA Frame (length:42, flags:0x01, stream_id:1)
           [recv] Timeout
      × 5: half closed (remote): Sends a DATA frame
        -> The endpoint MUST respond with a stream error of type STREAM_CLOSED.
           Expected: GOAWAY Frame (Error Code: STREAM_CLOSED)
                     RST_STREAM Frame (Error Code: STREAM_CLOSED)
                     Connection closed
             Actual: DATA Frame (length:42, flags:0x01, stream_id:1)

5.1/6

          [send] SETTINGS Frame (length:6, flags:0x00, stream_id:0)
           [recv] SETTINGS Frame (length:24, flags:0x00, stream_id:0)
           [send] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
           [recv] SETTINGS Frame (length:0, flags:0x01, stream_id:0)
           [send] HEADERS Frame (length:15, flags:0x05, stream_id:1)
           [send] HEADERS Frame (length:4, flags:0x05, stream_id:1)
           [recv] WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0)
           [recv] HEADERS Frame (length:49, flags:0x04, stream_id:1)
           [recv] DATA Frame (length:42, flags:0x01, stream_id:1)
           [recv] Timeout
      × 6: half closed (remote): Sends a HEADERS frame
        -> The endpoint MUST respond with a stream error of type STREAM_CLOSED.
           Expected: GOAWAY Frame (Error Code: STREAM_CLOSED)
                     RST_STREAM Frame (Error Code: STREAM_CLOSED)
                     Connection closed
             Actual: DATA Frame (length:42, flags:0x01, stream_id:1)

In both cases, the DATA frame is from the first request and there is the StreamError for the second request. Here is some info on send queue from the server side,

&http2.writeQueue{s:[]http2.FrameWriteRequest{
http2.FrameWriteRequest{write:(*http2.writeData)(0xc0004261b0), stream:(*http2.stream)(0xc000444000), done:(chan error)(0xc000414180)},
http2.FrameWriteRequest{write:http2.StreamError{StreamID:0x1, Code:0x5, Cause:error(nil)}, stream:(*http2.stream)(nil), done:(chan error)(nil)}}}

[summerwind]

Thanks for the log. It seems that h2spec is doing the expected behavior. Why does not your server immediately send a stream error?

[fraenkel]

Define immediately.he test case sends a HEADER frame with EndStream=true. This can result in a HEADER w/EndStream=true or HEADER + DATA (EndStream=true). Like I said, I haven't seen what the expected response is from the Server side. I can control the response to cause either of the above. If I have an empty handler, you get a HEADER only. If I send back some data, you get the later. If I only send back a HEADER, then I randomly fail with Actual: WINDOW_UPDATE Frame (length:4, flags:0x00, stream_id:0) which again is valid.

If I run all the h2spec tests with a server that sends no response data, I will fail anywhere from 3-7 tests. If I run with a server that sends some data back always, I get anywhere from 1-5 failing test cases. All of the failures but one are due to races between requests from the client and the internal state of the server.

[summerwind]

Make sense. All the tests of h2spec expects a response data. So you need to have endpoint that respond with HEADER + DATA frame.

If your server processes the first HEADER frame before receiving the second HEADER or DATA frame from h2spec in 5.1/5 or 5.1/6, your server should send a Stream error or Connection error after sending that response.

[fraenkel]

Well, now that I look at it closer its a bit more tricky. As I showed above, there is a RST_STREAM queued on stream 1, but because an END_STREAM was send to the client, the send queue for stream 1 is dropped. I will investigate how we should be handling that.

[fraenkel]

I am now convinced this test is racy. The race is ultimately between the responses of the first and second requests. If the first request sends a response, the stream is ended, so sending a RST_FRAME makes no sense since its already sent an END_STREAM on the the first response. If however, the response of the second request occurs first, then an RST_FRAME makes perfect sense.

This test cannot guarantee which response is actually sent back first.