net/http: apparent deadlock in TestRequestWriteTransport via dumpRequestOut

[bcmills]

2021-02-01T15:52:59-26e29aa/solaris-amd64-oraclerel
2019-10-15T20:29:56-831e3cf/solaris-amd64-oraclerel

goroutine 70 [select, 2 minutes]:
net/http.(*persistConn).roundTrip(0xc000376d80, 0xc0007043c0, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:2610 +0x765
net/http.(*Transport).roundTrip(0xc000386a00, 0xc0007e2b00, 0xc000254070, 0x0, 0xc0005d0288)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:592 +0xacb
net/http.(*Transport).RoundTrip(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/roundtrip.go:17
net/http.dumpRequestOut(0xc0007e2b00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:945 +0x305
net/http.TestRequestWriteTransport(0xc00024c300)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:788 +0x990
testing.tRunner(0xc00024c300, 0x948fd0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1194 +0xef
created by testing.(*T).Run
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1239 +0x2b3

…

goroutine 6197 [chan receive, 2 minutes]:
net/http.(*delegateReader).Read(0xc0005d0288, 0xc001273000, 0x1000, 0x1000, 0x8bfd00, 0x0, 0xc0003fd4d0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:961 +0xa9
net/http.(*persistConn).Read(0xc000376d80, 0xc001273000, 0x1000, 0x1000, 0x406cfd, 0x60, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc000498420)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc000498420, 0x1, 0xc0006f9b00, 0xc0003fd590, 0x44cfcc, 0xc000319078, 0x18)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc000376d80)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:2083 +0x1a8
created by net/http.(*Transport).dialConn
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:1743 +0xc77

…

goroutine 6195 [select, 2 minutes]:
io.(*pipe).Read(0xc000498060, 0xc001279000, 0x1000, 0x1000, 0x6, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/pipe.go:57 +0xcb
io.(*PipeReader).Read(0xc000254070, 0xc001279000, 0x1000, 0x1000, 0x6, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/pipe.go:134 +0x4c
bufio.(*Reader).fill(0xc0004984e0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).ReadSlice(0xc0004984e0, 0xc0002bc00a, 0xc001279004, 0x2, 0x1, 0x1000, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/bufio/bufio.go:360 +0x3d
net/http/internal.readChunkLine(0xc0004984e0, 0x2, 0x0, 0x0, 0x0, 0x2)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/internal/chunked.go:122 +0x34
net/http/internal.(*chunkedReader).beginChunk(0xc0002bc060)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/internal/chunked.go:48 +0x32
net/http/internal.(*chunkedReader).Read(0xc0002bc060, 0xc0011a8000, 0x2000, 0x2000, 0x1, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/internal/chunked.go:93 +0x134
net/http.(*body).readLocked(0xc0002d0100, 0xc0011a8000, 0x2000, 0x2000, 0x1, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transfer.go:842 +0x5f
net/http.(*body).Read(0xc0002d0100, 0xc0011a8000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transfer.go:834 +0xf9
io.discard.ReadFrom(0x7fffbf5a88d8, 0xc0002d0100, 0x8bf760, 0x1, 0x7fffbf5bd818)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/io.go:598 +0x95
io.copyBuffer(0x9c1a00, 0xc67440, 0x7fffbf5a88d8, 0xc0002d0100, 0x0, 0x0, 0x0, 0xc000806ec0, 0xc0007bc760, 0x100000001)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/io.go:409 +0x357
io.Copy(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/io.go:382
net/http.dumpRequestOut.func2(0xc000254070, 0x0, 0xc0005d0288)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:939 +0x24c
created by net/http.dumpRequestOut
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:931 +0x2e5

…

goroutine 6198 [chan receive, 2 minutes]:
net/http.finishAsyncByteRead.Read(0xc0002303c0, 0xc00088a000, 0x8000, 0x8000, 0x0, 0x0, 0x3)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transfer.go:1069 +0x65
io.(*multiReader).Read(0xc0001240d8, 0xc00088a000, 0x8000, 0x8000, 0x1, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/multi.go:26 +0xb2
io.copyBuffer(0x7fffbf5b2bf8, 0xc000b3a030, 0x9c0e00, 0xc0001240d8, 0xc00088a000, 0x8000, 0x8000, 0xc000c28c38, 0x40cee5, 0x8a5420)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/io.go:423 +0x12c
io.Copy(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/io/io.go:382
net/http.(*transferWriter).doBodyCopy(0xc0002303c0, 0x7fffbf5b2bf8, 0xc000b3a030, 0x9c0e00, 0xc0001240d8, 0x70b4b2, 0xc00079c3c0, 0xc001278000)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transfer.go:409 +0x6a
net/http.(*transferWriter).writeBody(0xc0002303c0, 0x9c1320, 0xc000010008, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transfer.go:356 +0x531
net/http.(*Request).write(0xc0007e2c00, 0x9c0a20, 0xc000704400, 0x0, 0xc0000b6d20, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/request.go:697 +0x7c6
net/http.(*persistConn).writeLoop(0xc000376d80)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:2385 +0x1a7
created by net/http.(*Transport).dialConn
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/transport.go:1744 +0xc9c

Note that:

go/src/net/http/requestwrite_test.go

Line 906 in 1b09d43

// dumpRequestOut is a modified copy of net/http/httputil.DumpRequestOut.

I wonder if the deadlock fixed httputil.DumpRequestOut fixed in CL 232798 (#38352) needs to be backported to the copy in the net/http/requestwrite_test.go, or if this is an unrelated bug.

CC @stevenh @neild @bradfitz @empijei

[stevenh]

Without the quitReadCh and the fix from #38352 you can definitely trigger a deadlock in the delegate reader for which the following would be a sign:

goroutine 6197 [chan receive, 2 minutes]:
net/http.(*delegateReader).Read(0xc0005d0288, 0xc001273000, 0x1000, 0x1000, 0x8bfd00, 0x0, 0xc0003fd4d0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:961 +0xa9

However the main goroutine hasn't returned yet, which was the trigger for that deadlock.

net/http.dumpRequestOut(0xc0007e2b00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/http/requestwrite_test.go:945 +0x305

So while I think it's a good idea to replicate the require changes to dumpRequestOut it looks like this is something else.