net/http, x/net/http2: net/http's TestNoSniffExpectRequestBody_h2 stops passing after x/net/http2 change in CL 253259 #42498
Description
$ go version go version devel +8f2db14cd3 Tue Nov 10 18:42:47 2020 +0000 darwin/amd64
With the following diff applied:
diff
diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index 5b92eb234b..8157806bcb 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -7632,6 +7632,9 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
// we can keep it.
bodyWriter.cancel()
cs.abortRequestBodyWrite(http2errStopReqBodyWrite)
+ if hasBody && !bodyWritten {
+ <-bodyWriter.resc
+ }
}
if re.err != nil {
cc.forgetStreamID(cs.ID)
@@ -7652,6 +7655,7 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
} else {
bodyWriter.cancel()
cs.abortRequestBodyWrite(http2errStopReqBodyWriteAndCancel)
+ <-bodyWriter.resc
}
cc.forgetStreamID(cs.ID)
return nil, cs.getStartedWrite(), http2errTimeout
@@ -7661,6 +7665,7 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
} else {
bodyWriter.cancel()
cs.abortRequestBodyWrite(http2errStopReqBodyWriteAndCancel)
+ <-bodyWriter.resc
}
cc.forgetStreamID(cs.ID)
return nil, cs.getStartedWrite(), ctx.Err()
@@ -7670,6 +7675,7 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
} else {
bodyWriter.cancel()
cs.abortRequestBodyWrite(http2errStopReqBodyWriteAndCancel)
+ <-bodyWriter.resc
}
cc.forgetStreamID(cs.ID)
return nil, cs.getStartedWrite(), http2errRequestCanceled
@@ -7679,6 +7685,7 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
// forgetStreamID.
return nil, cs.getStartedWrite(), cs.resetErr
case err := <-bodyWriter.resc:
+ bodyWritten = true
// Prefer the read loop's response, if available. Issue 16102.
select {
case re := <-readLoopResCh:
@@ -7689,7 +7696,6 @@ func (cc *http2ClientConn) roundTrip(req *Request) (res *Response, gotErrAfterRe
cc.forgetStreamID(cs.ID)
return nil, cs.getStartedWrite(), err
}
- bodyWritten = true
if d := cc.responseHeaderTimeout(); d != 0 {
timer := time.NewTimer(d)
defer timer.Stop()What did you do?
Pulled in latest version of x/net in CL 266898,
which includes the change in CL 253259,
then ran all.bash (and SlowBots). It failed with timeouts.
I narrowed it down to applying just the x/net/http2 change
of CL 253259 and the TestNoSniffExpectRequestBody_h2 test:
$ go test -short -v -run=TestNoSniffExpectRequestBody_h2 net/http
What did you expect to see?
$ go test -short -v -run=TestNoSniffExpectRequestBody_h2 net/http
=== RUN TestNoSniffExpectRequestBody_h2
--- PASS: TestNoSniffExpectRequestBody_h2 (0.00s)
PASS
ok net/http 0.369s
What did you see instead?
$ go test -short -v -run=TestNoSniffExpectRequestBody_h2 net/http
=== RUN TestNoSniffExpectRequestBody_h2
<stall until test times out>
Full Output
$ go test -short -v -timeout=60s -run=TestNoSniffExpectRequestBody_h2 net/http
=== RUN TestNoSniffExpectRequestBody_h2
panic: test timed out after 1m0s
goroutine 29 [running]:
testing.(*M).startAlarm.func1()
/Users/dmitshur/gotip/src/testing/testing.go:1680 +0xe5
created by time.goFunc
/Users/dmitshur/gotip/src/time/sleep.go:167 +0x45
goroutine 1 [chan receive]:
testing.(*T).Run(0xc000082900, 0x15295ad, 0x1f, 0x1549ca8, 0x1091f01)
/Users/dmitshur/gotip/src/testing/testing.go:1219 +0x2da
testing.runTests.func1(0xc000082780)
/Users/dmitshur/gotip/src/testing/testing.go:1491 +0x78
testing.tRunner(0xc000082780, 0xc0000d5d68)
/Users/dmitshur/gotip/src/testing/testing.go:1173 +0xef
testing.runTests(0xc0000b6138, 0x182eac0, 0x216, 0x216, 0xbfe2ea7af9323a28, 0xdf857cfc6, 0x1834180, 0x203000)
/Users/dmitshur/gotip/src/testing/testing.go:1489 +0x2fe
testing.(*M).Run(0xc000194000, 0x0)
/Users/dmitshur/gotip/src/testing/testing.go:1397 +0x1eb
net/http_test.TestMain(0xc000194000)
/Users/dmitshur/gotip/src/net/http/main_test.go:23 +0x2b
main.main()
_testmain.go:1179 +0x165
goroutine 19 [chan receive]:
net/http.(*http2ClientConn).roundTrip.func1(0xc00031a000, 0x0, 0x0, 0x0, 0x6, 0x2540be401, 0x5)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:7636 +0x21d
net/http.(*http2ClientConn).roundTrip(0xc000212300, 0xc00018d700, 0x0, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:7651 +0x1022
net/http.(*http2Transport).RoundTripOpt(0xc0000ae3f0, 0xc00018d700, 0xc00009c500, 0xc0000c0370, 0xc00009c530, 0x154b228)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:6972 +0x1a5
net/http.(*http2Transport).RoundTrip(0xc0000ae3f0, 0xc00018d700, 0x0, 0xc0000da0d8, 0x5)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:6933 +0x3a
net/http.(*Transport).roundTrip(0xc00009c500, 0xc00018d600, 0x1515fb6, 0x6, 0xc00018e4a8)
/Users/dmitshur/gotip/src/net/http/transport.go:590 +0x814
net/http.(*Transport).RoundTrip(...)
/Users/dmitshur/gotip/src/net/http/roundtrip.go:17
net/http_test.testNoSniffExpectRequestBody(0xc000082900, 0x127406f257f701)
/Users/dmitshur/gotip/src/net/http/clientserver_test.go:1339 +0x2ce
net/http_test.TestNoSniffExpectRequestBody_h2(0xc000082900)
/Users/dmitshur/gotip/src/net/http/clientserver_test.go:1321 +0x30
testing.tRunner(0xc000082900, 0x1549ca8)
/Users/dmitshur/gotip/src/testing/testing.go:1173 +0xef
created by testing.(*T).Run
/Users/dmitshur/gotip/src/testing/testing.go:1218 +0x2b3
goroutine 20 [IO wait]:
internal/poll.runtime_pollWait(0x7b1e7d8, 0x72, 0x0)
/Users/dmitshur/gotip/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000194098, 0x72, 0x0, 0x0, 0x1516106)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000194080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/internal/poll/fd_unix.go:401 +0x212
net.(*netFD).accept(0xc000194080, 0x4e0000c00020ad88, 0x100fc38, 0x4e2ee7a83207217e)
/Users/dmitshur/gotip/src/net/fd_unix.go:172 +0x45
net.(*TCPListener).accept(0xc0000b6150, 0x14fa2c0, 0xc0000a1c70, 0xc00020ae20)
/Users/dmitshur/gotip/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc0000b6150, 0x127406f26beb00, 0xc039489ca0, 0xc0000ae1c0, 0x0)
/Users/dmitshur/gotip/src/net/tcpsock.go:261 +0x65
crypto/tls.(*listener).Accept(0xc0000b6660, 0xc00020ae70, 0x18, 0xc000083080, 0x12f735b)
/Users/dmitshur/gotip/src/crypto/tls/tls.go:66 +0x37
net/http.(*Server).Serve(0xc0001a6000, 0x15ca650, 0xc0000b6660, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/http/server.go:2975 +0x285
net/http/httptest.(*Server).goServe.func1(0xc0000ae1c0)
/Users/dmitshur/gotip/src/net/http/httptest/server.go:308 +0x6e
created by net/http/httptest.(*Server).goServe
/Users/dmitshur/gotip/src/net/http/httptest/server.go:306 +0x5c
goroutine 22 [select]:
net/http.(*http2serverConn).serve(0xc000083680)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:4428 +0x579
net/http.(*http2Server).ServeConn(0xc0000ec880, 0x15d03d8, 0xc0000a9c00, 0xc0000d1b68)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:4038 +0x725
net/http.http2ConfigureServer.func1(0xc0001a6000, 0xc0000a9c00, 0x15c27e0, 0xc0000d8520)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:3864 +0xf0
net/http.(*conn).serve(0xc0000cadc0, 0x15cb2c0, 0xc000202060)
/Users/dmitshur/gotip/src/net/http/server.go:1855 +0x1555
created by net/http.(*Server).Serve
/Users/dmitshur/gotip/src/net/http/server.go:3007 +0x39b
goroutine 36 [IO wait]:
internal/poll.runtime_pollWait(0x7b1e6f0, 0x72, 0xffffffffffffffff)
/Users/dmitshur/gotip/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000194318, 0x72, 0x600, 0x6e9, 0xffffffffffffffff)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000194300, 0xc000260000, 0x6e9, 0x6e9, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000194300, 0xc000260000, 0x6e9, 0x6e9, 0x79fffff, 0xc00005f7c8, 0x101ab7e)
/Users/dmitshur/gotip/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000210000, 0xc000260000, 0x6e9, 0x6e9, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc000308030, 0xc000260000, 0x6e9, 0x6e9, 0x3, 0xc000080000, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:777 +0x63
bytes.(*Buffer).ReadFrom(0xc000214278, 0x15c13e0, 0xc000308030, 0x100d125, 0x14a50e0, 0x1501b40)
/Users/dmitshur/gotip/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc000214000, 0x7b22a40, 0xc000210000, 0x5, 0xc000210000, 0x20300000000000)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:799 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc000214000, 0x15cb200, 0xc0000a4008, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:606 +0x115
crypto/tls.(*Conn).readRecord(...)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:574
crypto/tls.(*Conn).Read(0xc000214000, 0xc000274000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:1277 +0x17f
bufio.(*Reader).Read(0xc00025d980, 0xc00026c1f8, 0x9, 0x9, 0x0, 0x10, 0x19433c8)
/Users/dmitshur/gotip/src/bufio/bufio.go:227 +0x222
io.ReadAtLeast(0x15c1200, 0xc00025d980, 0xc00026c1f8, 0x9, 0x9, 0x9, 0xc00005fcd8, 0x12bc13c, 0x14e0be0)
/Users/dmitshur/gotip/src/io/io.go:328 +0x87
io.ReadFull(...)
/Users/dmitshur/gotip/src/io/io.go:347
net/http.http2readFrameHeader(0xc00026c1f8, 0x9, 0x9, 0x15c1200, 0xc00025d980, 0x0, 0x0, 0xc00030a040, 0x0)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:1477 +0x89
net/http.(*http2Framer).ReadFrame(0xc00026c1c0, 0xc00030a040, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:1735 +0xa5
net/http.(*http2clientConnReadLoop).run(0xc00005ffa8, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:8303 +0xd8
net/http.(*http2ClientConn).readLoop(0xc000212300)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:8225 +0x6f
created by net/http.(*http2Transport).newClientConn
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:7198 +0x66e
goroutine 25 [IO wait]:
internal/poll.runtime_pollWait(0x7b1e608, 0x72, 0xffffffffffffffff)
/Users/dmitshur/gotip/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc000194398, 0x72, 0x200, 0x205, 0xffffffffffffffff)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
/Users/dmitshur/gotip/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000194380, 0xc0001a8240, 0x205, 0x205, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/internal/poll/fd_unix.go:166 +0x1d5
net.(*netFD).Read(0xc000194380, 0xc0001a8240, 0x205, 0x205, 0x200, 0xc0001a8240, 0x5)
/Users/dmitshur/gotip/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc0000aa070, 0xc0001a8240, 0x205, 0x205, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/net/net.go:183 +0x91
crypto/tls.(*atLeastReader).Read(0xc0000b6780, 0xc0001a8240, 0x205, 0x205, 0x200, 0x1834a40, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:777 +0x63
bytes.(*Buffer).ReadFrom(0xc0000a9e78, 0x15c13e0, 0xc0000b6780, 0x100d125, 0x14a50e0, 0x1501b40)
/Users/dmitshur/gotip/src/bytes/buffer.go:204 +0xbe
crypto/tls.(*Conn).readFromUntil(0xc0000a9c00, 0x7b22a40, 0xc0000aa070, 0x5, 0xc0000aa070, 0x9)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:799 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0000a9c00, 0x15cb200, 0xc0000a4008, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:606 +0x115
crypto/tls.(*Conn).readRecord(...)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:574
crypto/tls.(*Conn).Read(0xc0000a9c00, 0xc0001a6498, 0x9, 0x9, 0x0, 0x0, 0x0)
/Users/dmitshur/gotip/src/crypto/tls/conn.go:1277 +0x17f
io.ReadAtLeast(0x15c13a0, 0xc0000a9c00, 0xc0001a6498, 0x9, 0x9, 0x9, 0x0, 0x2, 0x1)
/Users/dmitshur/gotip/src/io/io.go:328 +0x87
io.ReadFull(...)
/Users/dmitshur/gotip/src/io/io.go:347
net/http.http2readFrameHeader(0xc0001a6498, 0x9, 0x9, 0x15c13a0, 0xc0000a9c00, 0x0, 0xc000000000, 0xc0000d3f70, 0xc0000909c0)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:1477 +0x89
net/http.(*http2Framer).ReadFrame(0xc0001a6460, 0xc0000d3f38, 0x0, 0x0, 0x2)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:1735 +0xa5
net/http.(*http2serverConn).readFrames(0xc000083680)
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:4314 +0xa9
created by net/http.(*http2serverConn).serve
/Users/dmitshur/gotip/src/net/http/h2_bundle.go:4420 +0x366
FAIL net/http 60.249s
FAIL
This may be related to #42256.