net/http: "missing status pseudo header" when reusing HTTP/2 connection

[leonklingele]

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

1.9.2

Does this issue reproduce with the latest release?

Yes

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

GOHOSTARCH="amd64"
GOHOSTOS="darwin"

What did you do?

Reusing an HTTP client resulted in a panic, example code: https://play.golang.org/p/DGUqwSMygZ
Unfortunately, I was unable to reproduce this issue again, still find it worth reporting it here.

Panic trace:

Got response!
failed to GET: missing status pseudo header
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x11d5340]

goroutine 7 [running]:
net/http.(*http2pipe).Write(0xc420457ce8, 0xc4200620e0, 0x51, 0x64, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:3661 +0x100
net/http.(*http2clientConnReadLoop).processData(0xc420489fb0, 0xc42007f560, 0xc42007f560, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:8259 +0x2ac
net/http.(*http2clientConnReadLoop).run(0xc420489fb0, 0x12a9300, 0xc4200357b0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7896 +0x54f
net/http.(*http2ClientConn).readLoop(0xc420080820)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7788 +0x9d
created by net/http.(*http2Transport).newClientConn
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7053 +0x6b9
exit status 2

The first request succeeded, (Got response!), the second one failed (failed to GET: missing status pseudo header) and most likely the third one caused the panic.
Is this a bug? Do Go HTTP clients need to be reinstantiated upon request failure?

[bradfitz]

Do Go HTTP clients need to be reinstantiated upon request failure?

No, they don't.

Which URL are you actually requesting? I'm wondering which server you're hitting.

Can you attach a trace with GODEBUG=http2debug=2 set?

/cc @tombergan

[leonklingele]

Can you attach a trace with GODEBUG=http2debug=2 set?

No unfortunately not. The crash only occurred once and never again since.

Which URL are you actually requesting?

I initially preferred to not disclose this information, maybe it might still help though:
The app happened to crash while trying to query various coin prices from Kraken using this library: https://github.com/nakatanakatana/cryptowatch-go
Example code here: https://play.golang.org/p/qvUGs3v24f

[leonklingele]

Good news, it crashed again 🎉

2017/11/26 18:56:47 http2: Transport encoding header ":authority" = "api.cryptowat.ch"
2017/11/26 18:56:47 http2: Transport encoding header ":method" = "GET"
2017/11/26 18:56:47 http2: Transport encoding header ":path" = "/markets/kraken/etceur/price"
2017/11/26 18:56:47 http2: Transport encoding header ":scheme" = "https"
2017/11/26 18:56:47 http2: Transport encoding header "accept-encoding" = "gzip"
2017/11/26 18:56:47 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/11/26 18:56:47 http2: Framer 0xc4201448c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=7 len=27
2017/11/26 18:56:48 http2: Framer 0xc4201448c0: read HEADERS flags=END_HEADERS stream=7 len=31
2017/11/26 18:56:48 http2: decoded hpack field header field "content-encoding" = "gzip"
2017/11/26 18:56:48 http2: decoded hpack field header field "content-type" = "application/json"
2017/11/26 18:56:48 http2: decoded hpack field header field "content-length" = "71"
2017/11/26 18:56:48 http2: decoded hpack field header field "date" = "Sun, 26 Nov 2017 17:56:48 GMT"
2017/11/26 18:56:48 http2: Transport received HEADERS flags=END_HEADERS stream=7 len=31
2017/11/26 18:56:48 http2: Framer 0xc4201448c0: wrote RST_STREAM stream=7 len=4 ErrCode=PROTOCOL_ERROR
2017/11/26 18:56:48 http2: Framer 0xc4201448c0: read DATA flags=END_STREAM stream=7 len=71 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\xff\xaaVJ\xcc\xc9\xc9/O\xccKNU\xb2\xaaVJ\xce/.Q\xb22365\xb7\xb0421\xd7Q*J\xcdM\xcc\xcc\xcb\xccKW\xb22\xa8\xad\xe5\x02\x04\x00\x00\xff\xff.\xa9\xda\xeb/\x00\x00\x00"
2017/11/26 18:56:48 http2: Transport received DATA flags=END_STREAM stream=7 len=71 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\xff\xaaVJ\xcc\xc9\xc9/O\xccKNU\xb2\xaaVJ\xce/.Q\xb22365\xb7\xb0421\xd7Q*J\xcdM\xcc\xcc\xcb\xccKW\xb22\xa8\xad\xe5\x02\x04\x00\x00\xff\xff.\xa9\xda\xeb/\x00\x00\x00"
2017/11/26 18:56:48 RoundTrip failure: missing status pseudo header
failed to query price: Get https://api.cryptowat.ch/markets/kraken/etceur/price: missing status pseudo header
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x11d5340]

goroutine 9 [running]:
net/http.(*http2pipe).Write(0xc4204cd928, 0xc420278000, 0x47, 0x64, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:3661 +0x100
net/http.(*http2clientConnReadLoop).processData(0xc420055fb0, 0xc420115590, 0x1c, 0xc420055ec8)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:8259 +0x2ac
net/http.(*http2clientConnReadLoop).run(0xc420055fb0, 0x12a9340, 0xc420468fb0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7896 +0x54f
net/http.(*http2ClientConn).readLoop(0xc420080340)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7788 +0x9d
created by net/http.(*http2Transport).newClientConn
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/h2_bundle.go:7053 +0x6b9

EDIT:
Interesting, the app crashed after querying the very last URL (price for etceur), therefore the crash is not related to reusing a connection but might be caused by destructing it?!

[bradfitz]

That's a bogus response from the api.cryptowat.ch HTTP/2 server.

Admittedly we should handle it better (not crash, whoops), but we also need to contact the author of that HTTP/2 server and get it fixed.

What do Chrome & Firefox do when :status is missing? Hopefully they're not permitting it and encouraging such violations.

/cc @tombergan @mcmanus @mnot

[mnot]

Did a quick tcpdump; that server doesn't appear to be negotiating H2, either with ALPN or Alt-Svc.

[leonklingele]

@mnot both h2i and Chrome do negotiate HTTP/2 on my side:

$ h2i api.cryptowat.ch
Connecting to api.cryptowat.ch:443 ...
Connected to 96.126.127.137:443
Negotiated protocol "h2"
Sending: []
[FrameHeader SETTINGS len=24]
  [MAX_FRAME_SIZE = 1048576]
  [MAX_CONCURRENT_STREAMS = 250]
  [MAX_HEADER_LIST_SIZE = 1048896]
  [INITIAL_WINDOW_SIZE = 1048576]
[FrameHeader WINDOW_UPDATE len=4]
  Window-Increment = 983041

[FrameHeader SETTINGS flags=ACK len=0]

[bradfitz]

It's possible it's only doing NPN and not ALPN. I can check later.

[mcmanus]

a response missing :status is a PROTOCOL_ERROR in firefox

[gopherbot]

Change https://golang.org/cl/80056 mentions this issue: http2: don't crash in Transport on server's DATA following bogus HEADERS

[bradfitz]

api.cryptowat.ch seems to do both NPN and ALPN.

Still not sure which HTTP/2 server it is.

https://cryptowat.ch/about says it was created by @artursapek. Artur, can you comment on which HTTP/2 server you're using for Cryptowatch? The HTTP/2 implementation seems buggy.

[artursapek]

hi @bradfitz. it's a net/http go server, actually. we're binding to ":443" directly using https://godoc.org/net/http#Server.ListenAndServeTLS to get the HTTP/2 features.

the binary on production was built with:

go version go1.9 linux/amd64

GOOS="linux"
GOARCH="amd64"

[bradfitz]

Well that's embarrassing.

@artursapek, thanks. I'll try to figure out how and where we're dropping :status.

[artursapek]

@bradfitz no worries, lmk if I can provide more specific details. and thanks for all your work on Go! we have a ton of gophers working hard for us over here.

[bradfitz]

@artursapek, I actually do see one way for this to happen, but it's weird: your http.Handler code would have to call ResponseWriter.WriteHeader(0). In that case, we record that the user set an explicit header and don't add the implicit 200.

Is it possible you ever call WriteHeader(0), even accidentally? Hopefully that's the case (because it's easy to fix) and it's not something else I'm not seeing.

[bradfitz]

I could imagine code like:

var status int
if someCondition {
    status = http.BadRequest
} else if otherCondition {
    status = 500
}
rw.WriteHeader(status)

... that would forget to set status.

[artursapek]

@bradfitz you're right, there was a case where we were failing to overwrite a default zero-value and passing that into WriteHeader. that branch of logic only happened in a timeout case (during moments of very high traffic), so that's why it was only happening occasionally from @leonklingele's perspective. I've deployed to production an update which fixes this.

[bradfitz]

Thanks for confirming. I'll fix the http2 server and make sure we're consistent in behavior from Go's API point of view between http1 and http2.

[gopherbot]

Change https://golang.org/cl/80076 mentions this issue: http2: panic on invalid WriteHeader status code

[bradfitz]

Also https://go-review.googlesource.com/c/go/+/80077/3 (in which I typoed this issue number).

[gopherbot]

Change https://golang.org/cl/80078 mentions this issue: net/http: update bundled http2