x/net/http2: panic on (*clientStream).bufPipe.Write

[rs]

Please answer these questions before submitting your issue. Thanks!

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

go1.8.3

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

freebsd, amd64

What did you do?

We a getting panics in http2 code while using it as a client (direct use of http2.Transport).
We are still trying to find a way to reproduce it.
Could be related to #20501.

What did you expect to see?

No panic.

What did you see instead?

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x6e21f7]

goroutine 3963 [running]:
golang.org/x/net/http2.(*pipe).Write(0xc42066e8e8, 0xc420790000, 0x56, 0x295, 0x0, 0x0, 0x0)
    src/golang.org/x/net/http2/pipe.go:85 +0x107
golang.org/x/net/http2.(*clientConnReadLoop).processData(0xc4201c0fb0, 0xc420397470, 0xc420397470, 0x0)
    src/golang.org/x/net/http2/transport.go:1819 +0x2dc
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc4201c0fb0, 0x7ec5e0, 0xc4201e87b0)
    src/golang.org/x/net/http2/transport.go:1467 +0x861
golang.org/x/net/http2.(*ClientConn).readLoop(0xc4207de340)
    src/golang.org/x/net/http2/transport.go:1359 +0xa6
created by golang.org/x/net/http2.(*Transport).newClientConn
    src/golang.org/x/net/http2/transport.go:535 +0x728

[odeke-em]

@rs I see this happens on go1.8.3, how about on go1.9rc2 or on tip? Also if possible perhaps a repro, please?

/cc @tombergan

[rs]

I’m using x/net/http2 directly so it should not be affected by the version of go.

I’m working on a repro.

[odeke-em]

@rs thanks for letting me know. Empirically I'd have thought that mattered because I could find go18.go, go19.go files in x/net/http2

$ find . -type f  -name "go[1-9]*"
./go16.go
./go17.go
./go17_not18.go
./go18.go
./go18_test.go
./go19.go
./go19_test.go

but on further examination, doesn't seem like a lot has changed at least between go1.8 and go1.9 in there so I get what you mean, thanks.

[rs]

One way to reproduce (I can't assert that's what happen here), is to have a broken server sending DATA frame before HEADERS frame. Here is a way to reproduce the crash:

https://play.golang.org/p/itUqFozrTC

2017/08/17 20:21:26 server: got preface: "PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n"
2017/08/17 20:21:26 server: write SETTINGS frame
2017/08/17 20:21:26 server: waiting for frame
2017/08/17 20:21:26 server: got frame: &http2.SettingsFrame{FrameHeader:http2.FrameHeader{valid:true, Type:0x4, Flags:0x0, Length:0x12, StreamID:0x0}, p:[]uint8{0x0, 0x2, 0x0, 0x0, 0x0, 0x0, 0x0, 0x4, 0x0, 0x40, 0x0, 0x0, 0x0, 0x6, 0x0, 0xa0, 0x0, 0x0}}
2017/08/17 20:21:26 server: sending SETTINGS ACK frame
2017/08/17 20:21:26 server: waiting for frame
2017/08/17 20:21:26 server: got frame: &http2.WindowUpdateFrame{FrameHeader:http2.FrameHeader{valid:true, Type:0x8, Flags:0x0, Length:0x4, StreamID:0x0}, Increment:0x40000000}
2017/08/17 20:21:26 server: waiting for frame
2017/08/17 20:21:26 client: sending request
2017/08/17 20:21:26 server: got frame: &http2.HeadersFrame{FrameHeader:http2.FrameHeader{valid:true, Type:0x1, Flags:0x5, Length:0x19, StreamID:0x1}, Priority:http2.PriorityParam{StreamDep:0x0, Exclusive:false, Weight:0x0}, headerFragBuf:[]uint8{0x81, 0x82, 0x84, 0x47, 0x0, 0x50, 0x83, 0x9b, 0xd9, 0xab, 0x7a, 0x8d, 0xc4, 0x75, 0xa7, 0x4a, 0x6b, 0x58, 0x94, 0x18, 0xb5, 0x25, 0x81, 0x2e, 0xf}}
2017/08/17 20:21:26 server: sending DATA frame
2017/08/17 20:21:26 server: waiting for frame
2017/08/17 20:21:26 server: got frame: &http2.SettingsFrame{FrameHeader:http2.FrameHeader{valid:true, Type:0x4, Flags:0x1, Length:0x0, StreamID:0x0}, p:[]uint8{}}
2017/08/17 20:21:26 server: sending SETTINGS ACK frame
2017/08/17 20:21:26 server: waiting for frame
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x11f0eb7]

goroutine 36 [running]:
golang.org/x/net/http2.(*pipe).Write(0xc4200f03e8, 0xc4200776a0, 0x4, 0xc, 0x0, 0x0, 0x0)
	/Users/rs/go/src/golang.org/x/net/http2/pipe.go:85 +0x107
golang.org/x/net/http2.(*clientConnReadLoop).processData(0xc42003afb0, 0xc42007d380, 0xc42007d380, 0x0)
	/Users/rs/go/src/golang.org/x/net/http2/transport.go:1832 +0x2cc
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc42003afb0, 0x129cd88, 0xc4200997b0)
	/Users/rs/go/src/golang.org/x/net/http2/transport.go:1468 +0x861
golang.org/x/net/http2.(*ClientConn).readLoop(0xc42008ad00)
	/Users/rs/go/src/golang.org/x/net/http2/transport.go:1359 +0xa6
created by golang.org/x/net/http2.(*Transport).newClientConn
	/Users/rs/go/src/golang.org/x/net/http2/transport.go:582 +0x728
exit status 2

cc @tombergan @bradfitz

[gopherbot]

Change https://golang.org/cl/56770 mentions this issue: http2: reject DATA frame before HEADERS frame

[tombergan]

Reopening: this is fixed in x/net/http2 but needs to be imported into net/http. I will do that eventually.

[rs]

FYI, this fix did not solve our panic issue. It must be another code path leading to a nil pipeBuffer.

[tombergan]

Are you using x/net/http2 directly or net/http? The fix has not been imported into net/http yet. If you're using x/net/http2, can you post a stack trace?

[rs]

Yes we are using x/net/http2 directly. Here is the stack trace:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x76a747]

goroutine 121 [running]:
golang.org/x/net/http2.(*pipe).Write(0xc4204c8668, 0xc420191500, 0x7, 0x1400, 0x0, 0x0, 0x0)
	src/golang.org/x/net/http2/pipe.go:85 +0x107
golang.org/x/net/http2.(*clientConnReadLoop).processData(0xc4202bdfb0, 0xc420522c90, 0xc420522c90, 0x0)
	src/golang.org/x/net/http2/transport.go:1831 +0x2ec
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc4202bdfb0, 0x89ba98, 0xc4202c6fb0)
	src/golang.org/x/net/http2/transport.go:1471 +0x7f8
golang.org/x/net/http2.(*ClientConn).readLoop(0xc4203d3040)
	src/golang.org/x/net/http2/transport.go:1359 +0xa6
created by golang.org/x/net/http2.(*Transport).newClientConn
	src/golang.org/x/net/http2/transport.go:535 +0x728

[rs]

@tombergan any clue?

[odeke-em]

@rs so I am using Go1.8.3 and I've gone through the net repo commit by commit, running the reproducer you posted.
Some actionable observations/questions:

1. Tip of x/net/http2 is at https://github.com/golang/net/tree/66aacef3dd8a676686c7ae3716979581e8b03c47/http2

https://github.com/golang/net/tree/1c05540f6879653db88113bc4a2b70aec4bd491f is the first hash on which I am able to reproduce your crash. From there on, I am able to keep the crash going until we encounter
https://github.com/golang/net/tree/5961165da77ad3a2abf3a77ea904c13a76b0b073/http2 which doesn't crash and successfully spits out a PROTOCOL_ERROR. That is about ~62 commits before your first fix at golang/net@57efc9c.
Here is a gist of the diff of what added, to make your repro break https://gist.github.com/odeke-em/d5f1690f0343885d4ce780f975576b3b

Therefore I assume your code was definitely before golang/net@57efc9c but probably after https://github.com/golang/net/tree/5961165da77ad3a2abf3a77ea904c13a76b0b073/http2.
If so, none of those commits' line numbers match your report in #21466 (comment), most of the last line crashes happen on 534 and that's 1 line from your crash report. I am also using Go1.8.3 which makes me think that perhaps that's a custom patched x/net/http2 that you are using?

2. Could you please provide the hash of the commit in your x/net repo currently for the latest report in x/net/http2: panic on (*clientStream).bufPipe.Write #21466 (comment) and for future crashes too?

[rs]

My code is locked on golang/net@59a0b19 with a few unrelated (waiting for upstream) patches. That's why the line numbers don't match.

I'm not using http2 thru the standard library but as a standalone lib so the version of Go should have minimal impact.

The reproducer I provided was based on an assumption of a code path the would lead to this panic. It was an actual bug but apparently not the bug hitting my code. There must be another code path that is problematic.