net/http: apparent deadlock in TestHandlerFinishSkipBigContentLengthRead

[bcmills]

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

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

Built from source at https://go.dev/cl/527196.

Does this issue reproduce with the latest release?

Presumably.

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

go env Output

$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/usr/local/google/home/bcmills/.cache/go-build'
GOENV='/usr/local/google/home/bcmills/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/usr/local/google/home/bcmills/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/usr/local/google/home/bcmills'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/google/home/bcmills/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='local'
GOTOOLDIR='/usr/local/google/home/bcmills/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='devel go1.22-965e2d4a89 Wed Sep 13 15:12:58 2023 -0400'
GCCGO='/usr/bin/gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/usr/local/google/home/bcmills/go/src/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build613896623=/tmp/go-build -gno-record-gcc-switches'

What did you do?

~/go/src$ while go test -race net/http -count=1 ; do true; done

What did you expect to see?

Consistently passing tests.

What did you see instead?

Lots of passing tests, followed by an apparent deadlock.

panic: test timed out after 10m0s
running tests:
        TestHandlerFinishSkipBigContentLengthRead (9m41s)

goroutine 15012 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2257 +0x214
created by time.goFunc
        /usr/local/google/home/bcmills/go/src/time/sleep.go:177 +0x45

goroutine 1 [chan receive, 9 minutes]:
testing.(*T).Run(0xc000104d00, {0xb8fdcc, 0x29}, 0xbbf158)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1647 +0x856
testing.runTests.func1(0x0?)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2052 +0x86
testing.tRunner(0xc000104d00, 0xc000137aa0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
testing.runTests(0xc000122d20?, {0xf97ac0, 0x210, 0x210}, {0xc00014c390?, 0x10?, 0xf9c3c0?})
        /usr/local/google/home/bcmills/go/src/testing/testing.go:2050 +0x897
testing.(*M).Run(0xc000122d20)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1923 +0xb58
net/http_test.TestMain(0x27f54a07e5eb5216?)
        /usr/local/google/home/bcmills/go/src/net/http/main_test.go:24 +0x65
main.main()
        _testmain.go:1169 +0x308

goroutine 48 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc0003044e0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http.TestCmdGoNoHTTPServer(0xc0003044e0)
        /usr/local/google/home/bcmills/go/src/net/http/http_test.go:55 +0x3f
testing.tRunner(0xc0003044e0, 0xbbeaa0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 49 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc000304680)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http.TestOmitHTTP2(0xc000304680)
        /usr/local/google/home/bcmills/go/src/net/http/http_test.go:89 +0xfa
testing.tRunner(0xc000304680, 0xbbeb48)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 50 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc000304820)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http.TestOmitHTTP2Vet(0xc000304820)
        /usr/local/google/home/bcmills/go/src/net/http/http_test.go:101 +0x3c
testing.tRunner(0xc000304820, 0xbbeb50)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 91 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc00029a680)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http.TestRequestWriteTransport(0xc00029a680)
        /usr/local/google/home/bcmills/go/src/net/http/requestwrite_test.go:668 +0x3f
testing.tRunner(0xc00029a680, 0xbbebd8)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 96 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc00029a4e0)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http.TestReadResponseCloseInMiddle(0xc00029a4e0)
        /usr/local/google/home/bcmills/go/src/net/http/response_test.go:647 +0x3f
testing.tRunner(0xc00029a4e0, 0xbbeba8)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 6455 [chan receive, 9 minutes]:
testing.(*T).Parallel(0xc0001ce340)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1401 +0x570
net/http_test.TestConsumingBodyOnNextConn(0xc0001ce340)
        /usr/local/google/home/bcmills/go/src/net/http/serve_test.go:166 +0x3f
testing.tRunner(0xc0001ce340, 0xbbef40)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b

goroutine 15029 [chan receive, 9 minutes]:
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0xc0006d1860)
        /usr/local/google/home/bcmills/go/src/net/http/serve_test.go:4602 +0x355
testing.tRunner(0xc0006d1860, 0xbbf158)
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1593 +0x21b
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go/src/testing/testing.go:1646 +0x82b
FAIL    net/http        600.041s
FAIL

(CC @neild)

[bcmills]

Notably, the goroutine dump shows neither the Server goroutine started by the test nor the serve goroutine that that call would have started for the connection. I don't know what to make of that. 😵‍💫

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-13 21:00 netbsd-386-9_3 go@399b2a4b net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 3m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (2m59s)

runtime.gopark(0x8550540, 0x8c25d70, 0xe, 0x17, 0x2)
	/tmp/workdir/go/src/runtime/proc.go:398 +0xfa fp=0x9238f00 sp=0x9238eec pc=0x808608a
runtime.chanrecv(0x8c25d40, 0x0, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x397 fp=0x9238f3c sp=0x9238f00 pc=0x804f707
runtime.chanrecv1(0x8c25d40, 0x0)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x1c fp=0x9238f50 sp=0x9238f3c pc=0x804f33c
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0x8ea9680)
	/tmp/workdir/go/src/net/http/serve_test.go:4602 +0x219 fp=0x9238f98 sp=0x9238f50 pc=0x8414a79
testing.tRunner(0x8ea9680, 0x854f4d0)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-14 13:15 netbsd-arm64-bsiegert go@d18e9407 net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 30m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (29m58s)

runtime.gopark(0x400019ae98?, 0x1e20c?, 0x0?, 0xc0?, 0x30?)
	/scratch/gobuilder/buildlet/go/src/runtime/proc.go:398 +0xc8 fp=0x400019ae20 sp=0x400019ae00 pc=0x4ac58
runtime.chanrecv(0x40006f4180, 0x0, 0x1)
	/scratch/gobuilder/buildlet/go/src/runtime/chan.go:583 +0x404 fp=0x400019aea0 sp=0x400019ae20 pc=0x174e4
runtime.chanrecv1(0x40004f6008?, 0x400178a000?)
	/scratch/gobuilder/buildlet/go/src/runtime/chan.go:442 +0x14 fp=0x400019aed0 sp=0x400019aea0 pc=0x170a4
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0x4000405d40)
	/scratch/gobuilder/buildlet/go/src/net/http/serve_test.go:4602 +0x1f0 fp=0x400019af60 sp=0x400019aed0 pc=0x369250
testing.tRunner(0x4000405d40, 0x4e8f70)

— watchflakes

[bcmills]

I got another one of these hammering on go test -race net net/http locally, so this does seem to be platform-independent and reproducible. I have no idea how it is happening, though. 🤔

(It took around 200 runs to reproduce.)

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-14 17:45 freebsd-amd64-race go@09300d89 net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 3m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (2m59s)

runtime.gopark(0x0?, 0x0?, 0x0?, 0xc0?, 0x30?)
	/tmp/workdir/go/src/runtime/proc.go:398 +0xce fp=0xc000537d80 sp=0xc000537d60 pc=0x49162e
runtime.chanrecv(0xc0003aea20, 0x0, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x36d fp=0xc000537df8 sp=0xc000537d80 pc=0x45d26d
runtime.chanrecv1(0xc0002f8008?, 0xc000930000?)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x12 fp=0xc000537e20 sp=0xc000537df8 pc=0x45ced2
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0xc0004b7ba0)
	/tmp/workdir/go/src/net/http/serve_test.go:4605 +0x355 fp=0xc000537ed0 sp=0xc000537e20 pc=0xa27c35
testing.tRunner(0xc0004b7ba0, 0xbe52a0)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-14 21:29 freebsd-386-13_0 go@a278550c net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 3m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (2m59s)

runtime.gopark(0x8553b08, 0x31bcb170, 0xe, 0x17, 0x2)
	/tmp/workdir/go/src/runtime/proc.go:398 +0xfa fp=0x319bbf00 sp=0x319bbeec pc=0x808610a
runtime.chanrecv(0x31bcb140, 0x0, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x397 fp=0x319bbf3c sp=0x319bbf00 pc=0x804f6c7
runtime.chanrecv1(0x31bcb140, 0x0)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x1c fp=0x319bbf50 sp=0x319bbf3c pc=0x804f2fc
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0x319b6a50)
	/tmp/workdir/go/src/net/http/serve_test.go:4605 +0x219 fp=0x319bbf98 sp=0x319bbf50 pc=0x8418129
testing.tRunner(0x319b6a50, 0x8552a8c)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-15 17:22 linux-arm64-race go@11b08a75 net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 3m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (2m58s)

runtime.gopark(0xc000793db8?, 0x4b8bc?, 0xf0?, 0x86?, 0x0?)
	/tmp/workdir/go/src/runtime/proc.go:398 +0xc8 fp=0xc000793d30 sp=0xc000793d10 pc=0x797c8
runtime.chanrecv(0xc000988540, 0x0, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x3a8 fp=0xc000793dc0 sp=0xc000793d30 pc=0x447d8
runtime.chanrecv1(0xc000992548?, 0xc00271a000?)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x14 fp=0xc000793df0 sp=0xc000793dc0 pc=0x443f4
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0xc0003536c0)
	/tmp/workdir/go/src/net/http/serve_test.go:4605 +0x314 fp=0xc000793eb0 sp=0xc000793df0 pc=0x500224
testing.tRunner(0xc0003536c0, 0x6b0898)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-15 15:33 netbsd-arm-bsiegert go@5f872db5 net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 30m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (29m52s)

runtime.gopark(0x54e87c, 0x1006030, 0xe, 0x17, 0x2)
	/var/gobuilder/buildlet/go/src/runtime/proc.go:398 +0x104 fp=0xd936fc sp=0xd936e8 pc=0x5466c
runtime.chanrecv(0x1006000, 0x0, 0x1)
	/var/gobuilder/buildlet/go/src/runtime/chan.go:583 +0x4b0 fp=0xd93738 sp=0xd936fc pc=0x17fc8
runtime.chanrecv1(0x1006000, 0x0)
	/var/gobuilder/buildlet/go/src/runtime/chan.go:442 +0x20 fp=0xd9374c sp=0xd93738 pc=0x17ae8
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0xea93b0)
	/var/gobuilder/buildlet/go/src/net/http/serve_test.go:4605 +0x230 fp=0xd93794 sp=0xd9374c pc=0x40e380
testing.tRunner(0xea93b0, 0x54d800)

— watchflakes

[bcmills]

I've been hitting this a bunch in TryBots, and given the failure rate I think it should be bisectable. Trying to git bisect now.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-18 18:40 netbsd-arm64-bsiegert go@3702cb5a net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 30m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (29m59s)

runtime.gopark(0x4000572e98?, 0x1e20c?, 0x30?, 0x20?, 0x30?)
	/scratch/gobuilder/buildlet/go/src/runtime/proc.go:398 +0xc8 fp=0x4000572e20 sp=0x4000572e00 pc=0x4ac58
runtime.chanrecv(0x40002be9c0, 0x0, 0x1)
	/scratch/gobuilder/buildlet/go/src/runtime/chan.go:583 +0x404 fp=0x4000572ea0 sp=0x4000572e20 pc=0x174e4
runtime.chanrecv1(0x400045a008?, 0x400185a000?)
	/scratch/gobuilder/buildlet/go/src/runtime/chan.go:442 +0x14 fp=0x4000572ed0 sp=0x4000572ea0 pc=0x170a4
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0x400050a9c0)
	/scratch/gobuilder/buildlet/go/src/net/http/serve_test.go:4608 +0x1f0 fp=0x4000572f60 sp=0x4000572ed0 pc=0x36a660
testing.tRunner(0x400050a9c0, 0x4e93a0)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHandlerFinishSkipBigContentLengthRead" && `panic: test timed out`

2023-09-18 20:42 darwin-amd64-race go@cc904eb0 net/http.TestHandlerFinishSkipBigContentLengthRead (log)

panic: test timed out after 6m0s
running tests:
	TestHandlerFinishSkipBigContentLengthRead (5m54s)

runtime.gopark(0x0?, 0x0?, 0x0?, 0x40?, 0x30?)
	/tmp/buildlet/go/src/runtime/proc.go:398 +0xce fp=0xc000d67d80 sp=0xc000d67d60 pc=0xa4618ae
runtime.chanrecv(0xc00022ca20, 0x0, 0x1)
	/tmp/buildlet/go/src/runtime/chan.go:583 +0x36d fp=0xc000d67df8 sp=0xc000d67d80 pc=0xa42d64d
runtime.chanrecv1(0xc000558238?, 0xc001154000?)
	/tmp/buildlet/go/src/runtime/chan.go:442 +0x12 fp=0xc000d67e20 sp=0xc000d67df8 pc=0xa42d2b2
net/http_test.TestHandlerFinishSkipBigContentLengthRead(0xc000cfb6c0)
	/tmp/buildlet/go/src/net/http/serve_test.go:4608 +0x355 fp=0xc000d67ed0 sp=0xc000d67e20 pc=0xa9f6b35
testing.tRunner(0xc000cfb6c0, 0xac76858)

— watchflakes