net: timeouts on dragonfly with goroutines in IO wait on UDPConn read methods

[gopherbot]

#!watchflakes
post <- goos == "dragonfly" && pkg == "net" && log ~ `test timed out` && log ~ `goroutine \d+ .*\[IO wait, \d+ minutes\]:\n(.+\n\t.+\n)*net\.\(\*UDPConn\)\.`

Issue created automatically to collect these failures.

Example (log):

panic: test timed out after 3m0s
running tests:
	TestAllocs (2m52s)

goroutine 1322 gp=0xc0003a2fc0 m=7 mp=0xc000316008 [running]:
panic({0x649e40?, 0xc0002ae040?})
	/tmp/workdir/go/src/runtime/panic.go:779 +0x158 fp=0xc0003c3f10 sp=0xc0003c3e60 pc=0x4390f8
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2366 +0x385 fp=0xc0003c3fe0 sp=0xc0003c3f10 pc=0x4f0605
runtime.goexit({})
...
net.TestReadWriteProlongedTimeout(0xc00026a680)
	/tmp/workdir/go/src/net/timeout_test.go:1028 +0x35 fp=0xc000184770 sp=0xc0001846b0 pc=0x6059b5
testing.tRunner(0xc00026a680, 0x6b0378)
	/tmp/workdir/go/src/testing/testing.go:1689 +0xfb fp=0xc0001847c0 sp=0xc000184770 pc=0x4ec33b
testing.(*T).Run.gowrap1()
	/tmp/workdir/go/src/testing/testing.go:1742 +0x25 fp=0xc0001847e0 sp=0xc0001847c0 pc=0x4ed365
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc0001847e8 sp=0xc0001847e0 pc=0x472101
created by testing.(*T).Run in goroutine 1
	/tmp/workdir/go/src/testing/testing.go:1742 +0x390

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2023-12-06 21:50 dragonfly-amd64-622 go@6ee27198 net (log)

panic: test timed out after 3m0s
running tests:
	TestAllocs (2m52s)

goroutine 1322 gp=0xc0003a2fc0 m=7 mp=0xc000316008 [running]:
panic({0x649e40?, 0xc0002ae040?})
	/tmp/workdir/go/src/runtime/panic.go:779 +0x158 fp=0xc0003c3f10 sp=0xc0003c3e60 pc=0x4390f8
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2366 +0x385 fp=0xc0003c3fe0 sp=0xc0003c3f10 pc=0x4f0605
runtime.goexit({})
...
net.TestReadWriteProlongedTimeout(0xc00026a680)
	/tmp/workdir/go/src/net/timeout_test.go:1028 +0x35 fp=0xc000184770 sp=0xc0001846b0 pc=0x6059b5
testing.tRunner(0xc00026a680, 0x6b0378)
	/tmp/workdir/go/src/testing/testing.go:1689 +0xfb fp=0xc0001847c0 sp=0xc000184770 pc=0x4ec33b
testing.(*T).Run.gowrap1()
	/tmp/workdir/go/src/testing/testing.go:1742 +0x25 fp=0xc0001847e0 sp=0xc0001847c0 pc=0x4ed365
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc0001847e8 sp=0xc0001847e0 pc=0x472101
created by testing.(*T).Run in goroutine 1
	/tmp/workdir/go/src/testing/testing.go:1742 +0x390

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

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

2023-12-09 21:48 dragonfly-amd64-622 go@46ea4ab5 net (log)

panic: test timed out after 3m0s
running tests:
	TestUDPServer (2m57s)
	TestUDPServer/17 (2m57s)

goroutine 1116 gp=0xc000412540 m=9 mp=0xc000324808 [running]:
panic({0x649e40?, 0xc0000a02b0?})
	/tmp/workdir/go/src/runtime/panic.go:779 +0x158 fp=0xc0002e2f10 sp=0xc0002e2e60 pc=0x4390f8
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2366 +0x385 fp=0xc0002e2fe0 sp=0xc0002e2f10 pc=0x4f0605
...
net.packetTransponder({0x6fa118, 0xc0002880d0}, 0xc0004107e0)
	/tmp/workdir/go/src/net/mockserver_test.go:449 +0x14d fp=0xc00034cf88 sp=0xc00034ced8 pc=0x5dbe6d
net.TestUDPServer.func1.1(0x0?, {0x6fa118?, 0xc0002880d0?})
	/tmp/workdir/go/src/net/server_test.go:271 +0x2d fp=0xc00034cfb0 sp=0xc00034cf88 pc=0x5f356d
net.(*localPacketServer).buildup.func1()
	/tmp/workdir/go/src/net/mockserver_test.go:404 +0x28 fp=0xc00034cfe0 sp=0xc00034cfb0 pc=0x5dbaa8
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc00034cfe8 sp=0xc00034cfe0 pc=0x472101
created by net.(*localPacketServer).buildup in goroutine 1140
	/tmp/workdir/go/src/net/mockserver_test.go:403 +0x67

— watchflakes

[bcmills]

(attn @golang/dragonfly)

[tuxillo]

Is there any way I can isolate the test case in a Go program?

[bcmills]

go test net will run these tests, although I suspect that this may be due to the kernel dropping loopback packets without returning errors for them — if so, it may be less likely to reproduce in isolation. 🙃

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "dragonfly" && pkg == "net" && log ~ `test timed out` && log ~ `goroutine \d+ .*\[IO wait, \d+ minutes\]:\n(.+\n\t.+\n)*net\.\(\*UDPConn\)\.`

2023-12-12 18:44 dragonfly-amd64-622 go@0ac1e3b2 net (log)

panic: test timed out after 3m0s
running tests:
	TestUDPServer (2m57s)
	TestUDPServer/26 (2m57s)

goroutine 1143 gp=0xc00029bc00 m=10 mp=0xc000299008 [running]:
panic({0x649b60?, 0xc00016a050?})
	/tmp/workdir/go/src/runtime/panic.go:779 +0x158 fp=0xc000100f10 sp=0xc000100e60 pc=0x4390d8
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2366 +0x385 fp=0xc000100fe0 sp=0xc000100f10 pc=0x4f05e5
...
net.packetTransponder({0x6f9c58, 0xc000306050}, 0xc00031e360)
	/tmp/workdir/go/src/net/mockserver_test.go:449 +0x14d fp=0xc00048e788 sp=0xc00048e6d8 pc=0x5dbe4d
net.TestUDPServer.func1.1(0x444a9d?, {0x6f9c58?, 0xc000306050?})
	/tmp/workdir/go/src/net/server_test.go:271 +0x2d fp=0xc00048e7b0 sp=0xc00048e788 pc=0x5f354d
net.(*localPacketServer).buildup.func1()
	/tmp/workdir/go/src/net/mockserver_test.go:404 +0x28 fp=0xc00048e7e0 sp=0xc00048e7b0 pc=0x5dba88
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc00048e7e8 sp=0xc00048e7e0 pc=0x4720e1
created by net.(*localPacketServer).buildup in goroutine 141
	/tmp/workdir/go/src/net/mockserver_test.go:403 +0x67

— watchflakes