net: TestDialerControlContext/StreamDial timeout with runnable syscall.Syscall goroutine

[gopherbot]

#!watchflakes
post <- pkg == "net" && test == "TestDialerControlContext" && `panic: test timed out` && log ~ `goroutine \d+ \[runnable\]:\nsyscall\.Syscall`

Issue created automatically to collect these failures.

Example (log):

panic: test timed out after 12m0s
running tests:
	TestDialerControlContext (11m59s)
	TestDialerControlContext/StreamDial (11m59s)

runtime.gopark(0x120361990, 0xc00005f248, 0xe, 0x17, 0x2)
	/tmp/gobuilder-mips64le/go/src/runtime/proc.go:398 +0x140 fp=0xc0004225e8 sp=0xc0004225d0 pc=0x120052f70
runtime.chanrecv(0xc00005f1f0, 0xc0004226cf, 0x1)
	/tmp/gobuilder-mips64le/go/src/runtime/chan.go:583 +0x5a4 fp=0xc000422658 sp=0xc0004225e8 pc=0x120009514
runtime.chanrecv1(0xc00005f1f0, 0xc0004226cf)
	/tmp/gobuilder-mips64le/go/src/runtime/chan.go:442 +0x2c fp=0xc000422680 sp=0xc000422658 pc=0x120008f14
testing.(*T).Run(0xc0002e0ea0, {0x12034a1e4, 0xa}, 0x120361590)
	/tmp/gobuilder-mips64le/go/src/testing/testing.go:1649 +0x4f0 fp=0xc000422738 sp=0xc000422680 pc=0x120140630
net.TestDialerControlContext(0xc0002e0ea0)
	/tmp/gobuilder-mips64le/go/src/net/dial_test.go:1030 +0x68 fp=0xc000422768 sp=0xc000422738 pc=0x12021c2b8
testing.tRunner(0xc0002e0ea0, 0x120360c00)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "net" && test == "TestDialerControlContext"

2023-09-06 19:37 linux-mips64le-rtrk go@729f214e net.TestDialerControlContext (log)

panic: test timed out after 12m0s
running tests:
	TestDialerControlContext (11m59s)
	TestDialerControlContext/StreamDial (11m59s)

runtime.gopark(0x120361990, 0xc00005f248, 0xe, 0x17, 0x2)
	/tmp/gobuilder-mips64le/go/src/runtime/proc.go:398 +0x140 fp=0xc0004225e8 sp=0xc0004225d0 pc=0x120052f70
runtime.chanrecv(0xc00005f1f0, 0xc0004226cf, 0x1)
	/tmp/gobuilder-mips64le/go/src/runtime/chan.go:583 +0x5a4 fp=0xc000422658 sp=0xc0004225e8 pc=0x120009514
runtime.chanrecv1(0xc00005f1f0, 0xc0004226cf)
	/tmp/gobuilder-mips64le/go/src/runtime/chan.go:442 +0x2c fp=0xc000422680 sp=0xc000422658 pc=0x120008f14
testing.(*T).Run(0xc0002e0ea0, {0x12034a1e4, 0xa}, 0x120361590)
	/tmp/gobuilder-mips64le/go/src/testing/testing.go:1649 +0x4f0 fp=0xc000422738 sp=0xc000422680 pc=0x120140630
net.TestDialerControlContext(0xc0002e0ea0)
	/tmp/gobuilder-mips64le/go/src/net/dial_test.go:1030 +0x68 fp=0xc000422768 sp=0xc000422738 pc=0x12021c2b8
testing.tRunner(0xc0002e0ea0, 0x120360c00)

— watchflakes

[bcmills]

This looks to me like a runtime/compiler bug: the test stalled for 12m, but the goroutine dump from panic shows a runnable goroutine.

[mknyszek]

It's not totally clear, since we don't know how long the goroutine was runnable for. In triage, Michael Pratt notes that it might be that a socket gets closed (perhaps via a defer or something?) as we're exiting that actually wakes up the goroutine in the syscall, but because the world is frozen, it can't get a P and ends up in the runnable state incidentally.

[mknyszek]

CC @golang/mips