net/http: apparent deadlock in TestTransportAndServerSharedBodyRace_h1 on OpenBSD

[bcmills]

A net/http test failure, seen only once so far:
2019-12-13T17:18:15-1475b97/openbsd-386-64

It's not obvious to me whether this is a bug in net/http, or a bug in the test. It kind of looks like we may have dropped a connection but failed to purge its persistConn, but I haven't had time to dig into it in detail. Lots of things blocked in I/O.

CC @bradfitz @ianlancetaylor

2019/12/13 09:35:46 http: TLS handshake error from 127.0.0.1:41529: read tcp 127.0.0.1:21271->127.0.0.1:41529: use of closed network connection
1 second passes in backend, proxygone= false
[…]
1 second passes in backend, proxygone= false
panic: test timed out after 3m0s

[…]

goroutine 1548 [select, 2 minutes]:
net/http.(*persistConn).roundTrip(0x67078c80, 0x6758ffa0, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/transport.go:2489 +0x670
net/http.(*Transport).roundTrip(0x67557800, 0x674ff500, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/transport.go:557 +0x8a9
net/http.(*Transport).RoundTrip(0x67557800, 0x674ff500, 0x67557800, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/roundtrip.go:17 +0x23
net/http.send(0x674ff500, 0x859f420, 0x67557800, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/tmp/workdir/go/src/net/http/client.go:252 +0x3b3
net/http.(*Client).send(0x6758fc20, 0x674ff500, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2, 0x80, 0x84bcb00, ...)
	/tmp/workdir/go/src/net/http/client.go:176 +0xa4
net/http.(*Client).do(0x6758fc20, 0x674ff500, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/client.go:692 +0x395
net/http.(*Client).Do(...)
	/tmp/workdir/go/src/net/http/client.go:560
net/http_test.testTransportAndServerSharedBodyRace(0x6728b400, 0x885a700)
	/tmp/workdir/go/src/net/http/serve_test.go:3998 +0x33e
net/http_test.TestTransportAndServerSharedBodyRace_h1(0x6728b400)
	/tmp/workdir/go/src/net/http/serve_test.go:3904 +0x20
testing.tRunner(0x6728b400, 0x85012f4)
	/tmp/workdir/go/src/testing/testing.go:954 +0xae
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1005 +0x2a7

[…]

goroutine 9342 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x498ebe48, 0x77, 0xffffffff)
	/tmp/workdir/go/src/runtime/netpoll.go:203 +0x45
internal/poll.(*pollDesc).wait(0x67261f54, 0x77, 0x0, 0x4038, 0xffffffff)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0x31
internal/poll.(*pollDesc).waitWrite(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).Write(0x67261f40, 0x67d98ff8, 0x3008, 0x7008, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:276 +0x208
net.(*netFD).Write(0x67261f40, 0x67d98ff8, 0x3008, 0x7008, 0x0, 0x2, 0x4)
	/tmp/workdir/go/src/net/fd_unix.go:220 +0x39
net.(*conn).Write(0x67538b40, 0x67d98ff8, 0x3008, 0x7008, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:196 +0x61
net/http.checkConnErrorWriter.Write(0x6793c000, 0x67d98ff8, 0x3008, 0x7008, 0x6, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/server.go:3434 +0x3d
bufio.(*Writer).Write(0x67110fc0, 0x67d98ff8, 0x3008, 0x7008, 0x6769cd48, 0x1, 0x1)
	/tmp/workdir/go/src/bufio/bufio.go:623 +0x117
net/http.(*chunkWriter).Write(0x67b4360c, 0x67d98000, 0x4000, 0x8000, 0x0, 0x82f21bf, 0x6793c048)
	/tmp/workdir/go/src/net/http/server.go:383 +0x6f
bufio.(*Writer).Write(0x675e3640, 0x67d98000, 0x4000, 0x8000, 0x67d98000, 0x8000, 0x8000)
	/tmp/workdir/go/src/bufio/bufio.go:623 +0x117
net/http.(*response).write(0x67b435f0, 0x4000, 0x67d98000, 0x4000, 0x8000, 0x0, 0x0, 0x6771bfc8, 0x6771bfc8, 0x8501964)
	/tmp/workdir/go/src/net/http/server.go:1578 +0x258
net/http.(*response).Write(0x67b435f0, 0x67d98000, 0x4000, 0x8000, 0x4000, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/server.go:1547 +0x47
io.copyBuffer(0x85a0640, 0x67538b60, 0x859f1e0, 0x67930660, 0x67d98000, 0x8000, 0x8000, 0x670c1f00, 0x67538b60, 0x67538b60, ...)
	/tmp/workdir/go/src/io/io.go:407 +0x18a
io.CopyBuffer(0x85a0640, 0x67538b60, 0x859f1e0, 0x67930660, 0x67d98000, 0x8000, 0x8000, 0x2b4, 0x8050f59, 0x67012000, ...)
	/tmp/workdir/go/src/io/io.go:378 +0x57
net/http.(*response).ReadFrom(0x67b435f0, 0x859f1e0, 0x67930660, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/server.go:582 +0x482
io.copyBuffer(0x859f720, 0x67b435f0, 0x859f1e0, 0x67930660, 0x0, 0x0, 0x0, 0x8051cf3, 0x846e140, 0x84af700, ...)
	/tmp/workdir/go/src/io/io.go:391 +0x295
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
io.CopyN(0x859f720, 0x67b435f0, 0x44d2a0c0, 0x6771bfb0, 0x100000, 0x0, 0x674f29b4, 0x0, 0x6777e540, 0x4)
	/tmp/workdir/go/src/io/io.go:340 +0x88
net/http_test.testTransportAndServerSharedBodyRace.func2.1(0x85a5100, 0x67b435f0, 0x674ff680, 0x6775f140)
	/tmp/workdir/go/src/net/http/serve_test.go:3930 +0x95
created by net/http_test.testTransportAndServerSharedBodyRace.func2
	/tmp/workdir/go/src/net/http/serve_test.go:3929 +0xaf

[…]

goroutine 9341 [select]:
net/http_test.testTransportAndServerSharedBodyRace.func2(0x85a5100, 0x67b435f0, 0x674ff680)
	/tmp/workdir/go/src/net/http/serve_test.go:3936 +0x13f
net/http.HandlerFunc.ServeHTTP(0x675389f8, 0x85a5100, 0x67b435f0, 0x674ff680)
	/tmp/workdir/go/src/net/http/server.go:2012 +0x2e
net/http.serverHandler.ServeHTTP(0x67b433b0, 0x85a5100, 0x67b435f0, 0x674ff680)
	/tmp/workdir/go/src/net/http/server.go:2807 +0x79
net/http.(*conn).serve(0x6793c000, 0x85a65a0, 0x675e32e0)
	/tmp/workdir/go/src/net/http/server.go:1895 +0x79e
created by net/http.(*Server).Serve
	/tmp/workdir/go/src/net/http/server.go:2933 +0x2b3

[…]

goroutine 9339 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x498ebb64, 0x72, 0xffffffff)
	/tmp/workdir/go/src/runtime/netpoll.go:203 +0x45
internal/poll.(*pollDesc).wait(0x67261f04, 0x72, 0x1000, 0x1000, 0xffffffff)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0x31
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0x67261ef0, 0x67aec000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:169 +0x162
net.(*netFD).Read(0x67261ef0, 0x67aec000, 0x1000, 0x1000, 0x1fe8, 0x0, 0x0)
	/tmp/workdir/go/src/net/fd_unix.go:202 +0x39
net.(*conn).Read(0x674b5f10, 0x67aec000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:184 +0x61
net/http.(*persistConn).Read(0x67078d20, 0x67aec000, 0x1000, 0x1000, 0x1fe8, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/transport.go:1816 +0x13f
bufio.(*Reader).Read(0x67335a40, 0x67af9fe8, 0x18, 0x18, 0x1fe8, 0x0, 0x0)
	/tmp/workdir/go/src/bufio/bufio.go:226 +0x1e7
net/http/internal.(*chunkedReader).Read(0x672ea040, 0x67af8000, 0x18, 0x18, 0x2000, 0x80bae5d, 0x67335a88)
	/tmp/workdir/go/src/net/http/internal/chunked.go:104 +0x1a8
net/http.(*body).readLocked(0x67335a70, 0x67af8000, 0x2000, 0x2000, 0x2000, 0x0, 0x80bae5d)
	/tmp/workdir/go/src/net/http/transfer.go:946 +0x48
net/http.(*body).Read(0x67335a70, 0x67af8000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/transfer.go:938 +0xc6
net/http.(*bodyEOFSignal).Read(0x67335aa0, 0x67af8000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/transport.go:2640 +0xba
io.(*LimitedReader).Read(0x67a00ac0, 0x67af8000, 0x2000, 0x2000, 0x2000, 0x0, 0x0)
	/tmp/workdir/go/src/io/io.go:451 +0x93
io/ioutil.devNull.ReadFrom(0x0, 0x859f1e0, 0x67a00ac0, 0x846e200, 0x848a300, 0x1, 0x44d2e2e8)
	/tmp/workdir/go/src/io/ioutil/ioutil.go:144 +0x75
io.copyBuffer(0x85a00a0, 0x88ad444, 0x859f1e0, 0x67a00ac0, 0x0, 0x0, 0x0, 0x8051cf3, 0x846e140, 0x848f9a0, ...)
	/tmp/workdir/go/src/io/io.go:391 +0x295
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
io.CopyN(0x85a00a0, 0x88ad444, 0x859f460, 0x67335aa0, 0x80000, 0x0, 0x44d2a0c0, 0x6771bf50, 0x674ff600, 0x0)
	/tmp/workdir/go/src/io/io.go:340 +0x88
net/http_test.testTransportAndServerSharedBodyRace.func4(0x85a5100, 0x67b43560, 0x674ff580)
	/tmp/workdir/go/src/net/http/serve_test.go:3964 +0x1f6
net/http.HandlerFunc.ServeHTTP(0x6758fbe0, 0x85a5100, 0x67b43560, 0x674ff580)
	/tmp/workdir/go/src/net/http/server.go:2012 +0x2e
net/http.serverHandler.ServeHTTP(0x67b43440, 0x85a5100, 0x67b43560, 0x674ff580)
	/tmp/workdir/go/src/net/http/server.go:2807 +0x79
net/http.(*conn).serve(0x6712bec0, 0x85a65a0, 0x675e28c0)
	/tmp/workdir/go/src/net/http/server.go:1895 +0x79e
created by net/http.(*Server).Serve
	/tmp/workdir/go/src/net/http/server.go:2933 +0x2b3

goroutine 9364 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x498ebb64, 0x77, 0xffffffff)
	/tmp/workdir/go/src/runtime/netpoll.go:203 +0x45
internal/poll.(*pollDesc).wait(0x67261f04, 0x77, 0x8000, 0x8000, 0xffffffff)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0x31
internal/poll.(*pollDesc).waitWrite(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).Write(0x67261ef0, 0x67aee000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:276 +0x208
net.(*netFD).Write(0x67261ef0, 0x67aee000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/fd_unix.go:220 +0x39
net.(*conn).Write(0x674b5f10, 0x67aee000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:196 +0x61
io.copyBuffer(0x85a0140, 0x674b5fa0, 0x859f1e0, 0x67a00a80, 0x67aee000, 0x8000, 0x8000, 0x3092c668, 0x1000be0, 0xc, ...)
	/tmp/workdir/go/src/io/io.go:407 +0x18a
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
net.genericReadFrom(0x859f3c0, 0x674b5f10, 0x859f1e0, 0x67a00a80, 0x2, 0x291, 0x8050f59, 0x67012000)
	/tmp/workdir/go/src/net/net.go:625 +0x85
net.(*TCPConn).readFrom(0x674b5f10, 0x859f1e0, 0x67a00a80, 0x8052431, 0x674a55f0, 0x1, 0x8051e38)
	/tmp/workdir/go/src/net/tcpsock_posix.go:54 +0x37
net.(*TCPConn).ReadFrom(0x674b5f10, 0x859f1e0, 0x67a00a80, 0x498eb068, 0x674b5f10, 0x859f301, 0x674bcdbc)
	/tmp/workdir/go/src/net/tcpsock.go:103 +0x39
io.copyBuffer(0x859f3c0, 0x674b5f10, 0x859f1e0, 0x67a00a80, 0x0, 0x0, 0x0, 0x846e200, 0x84977c0, 0x807cd01, ...)
	/tmp/workdir/go/src/io/io.go:391 +0x295
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
net/http.persistConnWriter.ReadFrom(0x67078d20, 0x859f1e0, 0x67a00a80, 0x498eb050, 0x67078d20, 0x1, 0x34d)
	/tmp/workdir/go/src/net/http/transport.go:1663 +0x6f
bufio.(*Writer).ReadFrom(0x670d5f20, 0x859f1e0, 0x67a00a80, 0x38488070, 0x670d5f20, 0x8053b01, 0x67a00a80)
	/tmp/workdir/go/src/bufio/bufio.go:714 +0x2d7
io.copyBuffer(0x859eea0, 0x670d5f20, 0x859f1e0, 0x67a00a80, 0x0, 0x0, 0x0, 0x1000, 0x7a, 0x0, ...)
	/tmp/workdir/go/src/io/io.go:391 +0x295
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
net/http.(*transferWriter).doBodyCopy(0x6708cff0, 0x859eea0, 0x670d5f20, 0x859f1e0, 0x67a00a80, 0x0, 0x1, 0x140, 0x8050f59)
	/tmp/workdir/go/src/net/http/transfer.go:401 +0x4f
net/http.(*transferWriter).writeBody(0x6708cff0, 0x859eea0, 0x670d5f20, 0x2, 0x2)
	/tmp/workdir/go/src/net/http/transfer.go:360 +0x606
net/http.(*Request).write(0x674ff600, 0x859eea0, 0x670d5f20, 0x0, 0x670d5f40, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/request.go:685 +0x5ac
net/http.(*persistConn).writeLoop(0x67078d20)
	/tmp/workdir/go/src/net/http/transport.go:2271 +0x157
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1639 +0xa48

goroutine 9362 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x498ec1c0, 0x77, 0xffffffff)
	/tmp/workdir/go/src/runtime/netpoll.go:203 +0x45
internal/poll.(*pollDesc).wait(0x67261d74, 0x77, 0x0, 0x1000, 0xffffffff)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0x31
internal/poll.(*pollDesc).waitWrite(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).Write(0x67261d60, 0x67ae3000, 0x2, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:276 +0x208
net.(*netFD).Write(0x67261d60, 0x67ae3000, 0x2, 0x1000, 0x670121d8, 0x498eb038, 0x3ff)
	/tmp/workdir/go/src/net/fd_unix.go:220 +0x39
net.(*conn).Write(0x674b5e80, 0x67ae3000, 0x2, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:196 +0x61
net/http.persistConnWriter.Write(0x67078c80, 0x67ae3000, 0x2, 0x1000, 0x80dcdea, 0x670d5e20, 0x84cb7e6)
	/tmp/workdir/go/src/net/http/transport.go:1654 +0x39
bufio.(*Writer).Flush(0x670d5e20, 0x674b5ef8, 0x84cb7e6)
	/tmp/workdir/go/src/bufio/bufio.go:591 +0x57
net/http/internal.(*chunkedWriter).Write(0x674b5f00, 0x67ae4000, 0x8000, 0x8000, 0x8000, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/internal/chunked.go:217 +0x149
io.copyBuffer(0x44d2a1c8, 0x674b5f00, 0x859f1e0, 0x679305e0, 0x67ae4000, 0x8000, 0x8000, 0x859f1e0, 0x679305e0, 0x679305e0, ...)
	/tmp/workdir/go/src/io/io.go:407 +0x18a
io.Copy(...)
	/tmp/workdir/go/src/io/io.go:364
net/http.(*transferWriter).doBodyCopy(0x6708cfa0, 0x44d2a1c8, 0x674b5f00, 0x859f1e0, 0x679305e0, 0x0, 0x1, 0x140, 0x8050f59)
	/tmp/workdir/go/src/net/http/transfer.go:401 +0x4f
net/http.(*transferWriter).writeBody(0x6708cfa0, 0x859eea0, 0x670d5e20, 0x2, 0x2)
	/tmp/workdir/go/src/net/http/transfer.go:349 +0x3ae
net/http.(*Request).write(0x674ff500, 0x859eea0, 0x670d5e20, 0x0, 0x670d5e60, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/http/request.go:685 +0x5ac
net/http.(*persistConn).writeLoop(0x67078c80)
	/tmp/workdir/go/src/net/http/transport.go:2271 +0x157
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1639 +0xa48

goroutine 9361 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x498ec1c0, 0x72, 0xffffffff)
	/tmp/workdir/go/src/runtime/netpoll.go:203 +0x45
internal/poll.(*pollDesc).wait(0x67261d74, 0x72, 0x1000, 0x1000, 0xffffffff)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0x31
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0x67261d60, 0x67ae2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:169 +0x162
net.(*netFD).Read(0x67261d60, 0x67ae2000, 0x1000, 0x1000, 0xffffffe1, 0x7fff, 0x8053b15)
	/tmp/workdir/go/src/net/fd_unix.go:202 +0x39
net.(*conn).Read(0x674b5e80, 0x67ae2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/net/net.go:184 +0x61
net/http.(*persistConn).Read(0x67078c80, 0x67ae2000, 0x1000, 0x1000, 0x40, 0x0, 0x80bae5d)
	/tmp/workdir/go/src/net/http/transport.go:1816 +0x13f
bufio.(*Reader).fill(0x67335a10)
	/tmp/workdir/go/src/bufio/bufio.go:100 +0xe5
bufio.(*Reader).Peek(0x67335a10, 0x1, 0x67a88440, 0x67549964, 0x67549950, 0x8500694, 0x81f40d9)
	/tmp/workdir/go/src/bufio/bufio.go:138 +0x3b
net/http.(*persistConn).readLoop(0x67078c80)
	/tmp/workdir/go/src/net/http/transport.go:1969 +0x194
created by net/http.(*Transport).dialConn
	/tmp/workdir/go/src/net/http/transport.go:1638 +0xa27
FAIL	net/http	180.151s

[bcmills]

Also appears to affect openbsd-amd64:
2021-05-12T15:04:42-af0f8c1/openbsd-amd64-64

CC @4a6f656c

[bcmills]

This looks close enough to #49336 that I suspect they're the same issue.

[bcmills]

Duplicate of #49336