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

x/net/http2: h2spec violation 5.1 #26322

Open
fraenkel opened this Issue Jul 11, 2018 · 11 comments

Comments

Projects
None yet
3 participants
@fraenkel
Contributor

fraenkel commented Jul 11, 2018

$ ./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

This comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

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 comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

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

This comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

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

This comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

Opened summerwind/h2spec#89 for 5.1/5

@ianlancetaylor ianlancetaylor added this to the Go1.12 milestone Jul 11, 2018

@fraenkel

This comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

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

This comment has been minimized.

Contributor

fraenkel commented Jul 11, 2018

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

@fraenkel

This comment has been minimized.

Contributor

fraenkel commented Jul 12, 2018

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

This comment has been minimized.

Member

bradfitz commented Jul 12, 2018

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

Also, what's your server code?

@fraenkel

This comment has been minimized.

Contributor

fraenkel commented Jul 12, 2018

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

This comment has been minimized.

Contributor

fraenkel commented Jul 12, 2018

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

@fraenkel

This comment has been minimized.

Contributor

fraenkel commented Jul 12, 2018

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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment