x/net/http2: timeouts not respected on malformed data frames

[danslo]

What version of Go are you using (go version)?

$ go version
go version go1.19.4 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

Darwin / ARM64 / AMD64, but also reproduced on Linux / AMD64.

What did you do?

Run the following code with server that completes TLS handshake, but then just sends random raw data. In other words, our client never receives frame with flags=END_STREAM.

func main() {
    ctx, cancel := context.WithTimeout(context.Background(), time.Duration(3*time.Second))
    defer cancel()
    cl := &http.Client{Timeout: 3 * time.Second}
    req, _ := http.NewRequestWithContext(ctx, "GET", os.Args[1], nil)
    cl.Do(req)
}

What did you expect to see?

After 3 seconds, the connection is aborted.

What did you see instead?

The connection hangs indefinitely.

Additional Context

We've seen this happen with Cloudflare in front of a non-http(s) backend. In this case we assume it is wrongly configured to point at a SSH daemon. Even in that case, we should not hang forever.

Running with GODEBUG=http2debug=2:

2023/01/17 19:17:30 http2: Transport failed to get client conn for <snip>:443: http2: no cached connection was available
2023/01/17 19:17:30 http2: Transport creating client conn 0xc0000a8180 to [<snip>]:443
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2023/01/17 19:17:30 http2: Transport encoding header ":authority" = "<snip>"
2023/01/17 19:17:30 http2: Transport encoding header ":method" = "GET"
2023/01/17 19:17:30 http2: Transport encoding header ":path" = "/"
2023/01/17 19:17:30 http2: Transport encoding header ":scheme" = "https"
2023/01/17 19:17:30 http2: Transport encoding header "accept-encoding" = "gzip"
2023/01/17 19:17:30 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=39
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=256, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
2023/01/17 19:17:30 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=256, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: wrote SETTINGS flags=ACK len=0
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: read WINDOW_UPDATE len=4 (conn) incr=2147418112
2023/01/17 19:17:30 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: read SETTINGS flags=ACK len=0
2023/01/17 19:17:30 http2: Transport received SETTINGS flags=ACK len=0
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: read HEADERS flags=END_HEADERS stream=1 len=417
2023/01/17 19:17:30 http2: decoded hpack field header field ":status" = "101"
2023/01/17 19:17:30 http2: decoded hpack field header field "date" = "Tue, 17 Jan 2023 18:17:31 GMT"
2023/01/17 19:17:30 http2: decoded hpack field header field "cf-cache-status" = "DYNAMIC"
2023/01/17 19:17:30 http2: decoded hpack field header field "report-to" = "{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v3?s=<snip>\"}],\"group\":\"cf-nel\",\"max_age\":604800}"
2023/01/17 19:17:30 http2: decoded hpack field header field "nel" = "{\"success_fraction\":0,\"report_to\":\"cf-nel\",\"max_age\":604800}"
2023/01/17 19:17:30 http2: decoded hpack field header field "server" = "cloudflare"
2023/01/17 19:17:30 http2: decoded hpack field header field "cf-ray" = "78b116903a38731a-LHR"
2023/01/17 19:17:30 http2: decoded hpack field header field "alt-svc" = "h3=\":443\"; ma=86400, h3-29=\":443\"; ma=86400"
2023/01/17 19:17:30 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=417
2023/01/17 19:17:30 http2: Framer 0xc0000e0460: read DATA stream=1 len=41 data="SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.5\r\n"
2023/01/17 19:17:30 http2: Transport received DATA stream=1 len=41 data="SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.5\r\n"

x/net/http2 also provides a ReadIdleTimeout and PingTimeout. According to the docs:

ReadIdleTimeout is the timeout after which a health check using ping frame will be carried out if no frame is received on the connection.

PingTimeout is the timeout after which the connection will be closed if a response to Ping is not received.

So the following was tried:

func main() {
    t2 := &http2.Transport{
        ReadIdleTimeout: 3 * time.Second,
        PingTimeout:     1 * time.Second,
    }
    cl := &http.Client{Transport: t2}
    req, _ := http.NewRequest("GET", os.Args[1], nil)
    cl.Do(req)
}

This still hangs indefinitely.

[cherrymui]

cc @neild @tombergan

[danslo]

FWIW the URL in question is https://enablewebdesign.com - let me know if you need any other information or a more local way to reproduce..

curl exits immediately:

$ curl --http2 https://enablewebdesign.com 
curl: (92) HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)

[gwillem]

Verified with go 1.19.5 @ darwin/arm64. For the record, this issue effectively creates a DoS, since there is (afaik?) no other way to enforce a timeout.

[fraenkel]

here is the crux of the issue, a panic

golang.org/x/net/http2.(*ClientConn).readLoop.func1()
    /home/go/src/golang.org/x/net/http2/transport.go:2118 +0x26 fp=0xc000157b48 sp=0xc000157b30 pc=0x7016c6
runtime.deferCallSave(0xc000157c18, 0xc000157fa0?)
    /usr/local/go/src/runtime/panic.go:796 +0x88 fp=0xc000157b58 sp=0xc000157b48 pc=0x4386e8
runtime.runOpenDeferFrame(0xc0004493b0?, 0xc000449360)
    /usr/local/go/src/runtime/panic.go:769 +0x1a5 fp=0xc000157ba0 sp=0xc000157b58 pc=0x438505
panic({0x7dd3a0, 0xb44700})
    /usr/local/go/src/runtime/panic.go:884 +0x212 fp=0xc000157c60 sp=0xc000157ba0 pc=0x438952
runtime.panicmem(...)
    /usr/local/go/src/runtime/panic.go:260
runtime.sigpanic()
    /usr/local/go/src/runtime/signal_unix.go:835 +0x2f6 fp=0xc000157cb0 sp=0xc000157c60 pc=0x44f576
golang.org/x/net/http2.(*pipe).Write(0xc000157d60?, {0xc0001aa1a0?, 0x180?, 0x75?})
    /home/go/src/golang.org/x/net/http2/pipe.go:98 +0x17b fp=0xc000157d38 sp=0xc000157cb0 pc=0x6e6d7b
golang.org/x/net/http2.(*clientConnReadLoop).processData(0xc000157f98, 0xc00007eae0)
    /home/go/src/golang.org/x/net/http2/transport.go:2669 +0x225 fp=0xc000157e00 sp=0xc000157d38 pc=0x704ac5
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc000157f98)
    /home/go/src/golang.org/x/net/http2/transport.go:2258 +0x6e5 fp=0xc000157f60 sp=0xc000157e00 pc=0x702625
golang.org/x/net/http2.(*ClientConn).readLoop(0xc0001b0180)
    /home/go/src/golang.org/x/net/http2/transport.go:2119 +0x6f fp=0xc000157fc8 sp=0xc000157f60 pc=0x70158f
golang.org/x/net/http2.(*Transport).newClientConn.func1()
    /home/go/src/golang.org/x/net/http2/transport.go:817 +0x26 fp=0xc000157fe0 sp=0xc000157fc8 pc=0x6fa566
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000157fe8 sp=0xc000157fe0 pc=0x46bde1
created by golang.org/x/net/http2.(*Transport).newClientConn
    /home/go/src/golang.org/x/net/http2/transport.go:817 +0xc5c

[fraenkel]

The actual issue is failing to treat a 101 response as a PROTOCOL_ERROR.

[gopherbot]

Change https://go.dev/cl/463095 mentions this issue: http2: reject 101 status code

[gopherbot]

Change https://go.dev/cl/463497 mentions this issue: http2: reject DATA frames read before headers are finished

[neild]

I don't think the handling of 101 responses is the problem; we'd encounter the same issue if the server had sent a 102 instead. The issue is that we're trying to process a DATA frame (or what looks like one) before the final headers have been read., which causes an internal panic. The panic is then obscured by a deferred cleanup function that gets stuck waiting on a mutex that was locked when the panic happened.

[fraenkel]

Doesn't your fix handle https://github.com/golang/go/issues/43965 as well?

[neild]

Yes, #43965 looks to be the same thing. And you have a fix for that one in CL https://go.dev/cl/330415 (exact same change as my CL, heh) which seems to have fallen through the Gerrit cracks somehow.