x/net/http2: h2spec violation 5.1

[fraenkel]

$ ./h2spec -S -k -t -h 127.0.0.1 -p 8080 http2/5.1
Failures: 

Hypertext Transfer Protocol Version 2 (HTTP/2)
  5. Streams and Multiplexing
    5.1. Stream States
      × 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)
      × 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)

These tests don't always fail so it is most likely an issue with the h2spec test.

[fraenkel]

The test makes broad assumptions about how the server responds. In my case, the server send back some bogus message which triggered a race between the data frame and the streamError. Switching to an empty handler, just moved the problem....

Hypertext Transfer Protocol Version 2 (HTTP/2)
  5. Streams and Multiplexing
    5.1. Stream States
      × 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)

[fraenkel]

This I believe is an h2spec issue given 5.1 states:

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]

5.1/6 is now reporting:

    × 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: HEADERS Frame (length:28, flags:0x05, stream_id:1)

[fraenkel]

Opened https://github.com/summerwind/h2spec/issues/89 for 5.1/5

[fraenkel]

5.1/6 has a similar issue with 5.1/5. There is a race between the response of the first frame (HEADERS) and the response of the second request.

[fraenkel]

I don't believe there is anything to do here.

[fraenkel]

I am mistaken. @bradfitz This is a valid bug.

Both 5.1/5 and 5.1/6 are variations of the same issue. A HEADER frame is sent with END_STREAM=true followed by a second frame HEADER or DATA with END_STREAM=true. The receipt of the second frame while in half-closed remote should trigger a RST_FRAME. There are multiple possible outcomes because of the various queuing that occurs in the server.

The failure scenario has the response of both requests put on the stream 1 queue. When the response for the first request is sent back, we delete the queue. The RST_FRAME for the second request never occurs.

One way to fix this is to reset the stream only when the queue length is 0.

[bradfitz]

Can you send the GODEBUG=http2debug=2 output from the Go server side while the test fails?

Also, what's your server code?

[fraenkel]

Nevermind, its racy. We already sent an END_STREAM for id=1 on the first response so sending an RST_FRAME would be odd.

[fraenkel]

The server code for all tests are https://play.golang.org/p/-K6vYPNCFG2

[fraenkel]

For some reason, sending a HEADER(END_STREAM=true) + DATA(END_STREAM=true) tends to pass but HEADER (ES=true) + HEADER(ES=true) fails.

The only difference between pass/fail is whether the response for request 2 is sent first or not.

FAIL

2018/07/12 11:23:48 http2: server connection from 127.0.0.1:40584 on 0xc000099380
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=4320, INITIAL_WINDOW_SIZE=1048576
2018/07/12 11:23:48 http2: server: client 127.0.0.1:40584 said hello
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: read SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=65535
2018/07/12 11:23:48 http2: server read frame SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=65535
2018/07/12 11:23:48 http2: server processing setting [INITIAL_WINDOW_SIZE = 65535]
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote SETTINGS flags=ACK len=0
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: read SETTINGS flags=ACK len=0
2018/07/12 11:23:48 http2: server read frame SETTINGS flags=ACK len=0
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=15
2018/07/12 11:23:48 http2: decoded hpack field header field ":method" = "GET"
2018/07/12 11:23:48 http2: decoded hpack field header field ":scheme" = "https"
2018/07/12 11:23:48 http2: decoded hpack field header field ":path" = "/"
2018/07/12 11:23:48 http2: decoded hpack field header field ":authority" = "127.0.0.1:8080"
2018/07/12 11:23:48 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=1 len=15
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: read DATA flags=END_STREAM stream=1 len=4 data="test"
2018/07/12 11:23:48 http2: server read frame DATA flags=END_STREAM stream=1 len=4 data="test"
2018/07/12 11:23:48 http2: server encoding header ":status" = "200"
2018/07/12 11:23:48 http2: server encoding header "content-type" = "text/html; charset=utf-8"
2018/07/12 11:23:48 http2: server encoding header "content-length" = "42"
2018/07/12 11:23:48 http2: server encoding header "date" = "Thu, 12 Jul 2018 15:23:48 GMT"
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote HEADERS flags=END_HEADERS stream=1 len=49
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote WINDOW_UPDATE len=4 (conn) incr=4
2018/07/12 11:23:48 http2: Framer 0xc0001820e0: wrote DATA flags=END_STREAM stream=1 len=42 data="<h1><center> Hello from Go! </h1></center>"

PASS

2018/07/12 11:23:57 http2: server connection from 127.0.0.1:40586 on 0xc000099520
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=4320, INITIAL_WINDOW_SIZE=1048576
2018/07/12 11:23:57 http2: server: client 127.0.0.1:40586 said hello
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: read SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=65535
2018/07/12 11:23:57 http2: server read frame SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=65535
2018/07/12 11:23:57 http2: server processing setting [INITIAL_WINDOW_SIZE = 65535]
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: wrote SETTINGS flags=ACK len=0
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: read SETTINGS flags=ACK len=0
2018/07/12 11:23:57 http2: server read frame SETTINGS flags=ACK len=0
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=15
2018/07/12 11:23:57 http2: decoded hpack field header field ":method" = "GET"
2018/07/12 11:23:57 http2: decoded hpack field header field ":scheme" = "https"
2018/07/12 11:23:57 http2: decoded hpack field header field ":path" = "/"
2018/07/12 11:23:57 http2: decoded hpack field header field ":authority" = "127.0.0.1:8080"
2018/07/12 11:23:57 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=1 len=15
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: read DATA flags=END_STREAM stream=1 len=4 data="test"
2018/07/12 11:23:57 http2: server read frame DATA flags=END_STREAM stream=1 len=4 data="test"
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: wrote WINDOW_UPDATE len=4 (conn) incr=4
2018/07/12 11:23:57 http2: Framer 0xc0001820e0: wrote RST_STREAM stream=1 len=4 ErrCode=STREAM_CLOSED