net/http: timeout in TestIssue4191_InfiniteGetTimeout on wasip1/wasm

[bcmills]

#!watchflakes
post <- goarch == "wasm" && pkg == "net/http" && test == "TestIssue4191_InfiniteGetTimeout" && log ~ `panic: test timed out` && date < "2024-02-01"

Go version

e1c0349

Output of go env in your module/workspace:

N/A

What did you do?

#64321 (comment)

What did you see happen?

panic: test timed out after 3m0s
running tests:
	TestIssue4191_InfiniteGetTimeout/h1 (2m4s)

What did you expect to see?

All tests passing.

(attn @neild @golang/wasm)

[bcmills]

I'm able to reproduce this locally with:

GOARCH=wasm GOOS=wasip1 go test net/http -run=TestIssue4191_InfiniteGetTimeout -count=1000 -timeout=150s

I think this might be a runtime scheduler fairness issue (attn @golang/wasm @golang/runtime). In the failure log I see:

goroutine 15299 gp=0x28fa380 m=nil [runnable]:
net.(*deadlineTimer).Reset.func3()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/net_fake.go:669 fp=0x1853fe0 sp=0x1853fd8 pc=0x21d40000
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x1853fe8 sp=0x1853fe0 pc=0x15580001
created by time.goFunc
	/home/swarming/.swarming/w/ir/x/w/goroot/src/time/sleep.go:177 +0x5

That is the callback that is supposed to close the expired channel when the socket's deadline timer expires. However, in this test there are two other goroutines running, and at least one of them is always runnable:

• If the receive buffer is not full, then the server goroutine is runnable. (It can write to the packetQueue without blocking.)
• If the receive buffer is full, then the client goroutine is runnable. (It can read from the packetQueue without blocking.)

My hypothesis: maybe it is possible to get into a state in which the scheduler alternates between the server and client goroutines, always choosing one of those in favor of the runnable deadlineTimer goroutine?

[bcmills]

Confirmed a runtime starvation bug using a much simpler reproducer (#65178).

I think I can work around it in the net stack using a call to runtime.Gosched, although that shouldn't really be necessary in the first place.

[gopherbot]

Change https://go.dev/cl/557037 mentions this issue: net: work around runtime scheduler starvation on js and wasip1

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goarch == "wasm" && pkg == "net/http" && test == "TestIssue4191_InfiniteGetTimeout" && log ~ `panic: test timed out` && date < "2024-02-01"

2024-01-08 17:02 gotip-wasip1-wasm_wazero go@10a66d68 net/http.TestIssue4191_InfiniteGetTimeout (log)

=== RUN   TestIssue4191_InfiniteGetTimeout/h1
=== PAUSE TestIssue4191_InfiniteGetTimeout/h1
=== CONT  TestIssue4191_InfiniteGetTimeout/h1
panic: test timed out after 3m0s
running tests:
	TestIssue4191_InfiniteGetTimeout/h1 (2m2s)

goroutine 15301 gp=0x21d6a80 m=0 mp=0x714160 [running]:
panic({0x4fe60, 0x19143a0})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:779 +0x1f fp=0x23e9f00 sp=0x23e9e58 pc=0x1293001f
...
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa fp=0x21f1f60 sp=0x21f1f10 pc=0x344a000a
testing.tRunner(0x23df860, 0x2098840)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd fp=0x21f1fc8 sp=0x21f1f60 pc=0x1b1f000d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x2 fp=0x21f1fe0 sp=0x21f1fc8 pc=0x1b250002
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x21f1fe8 sp=0x21f1fe0 pc=0x15580001
created by testing.(*T).Run in goroutine 1251
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goarch == "wasm" && pkg == "net/http" && test == "TestIssue4191_InfiniteGetTimeout" && log ~ `panic: test timed out` && date < "2024-02-01"

2024-01-04 20:40 go1.22-wasip1-wasm_wazero release-branch.go1.22@1e07c144 net/http.TestIssue4191_InfiniteGetTimeout [ABORT] (log)

=== RUN   TestIssue4191_InfiniteGetTimeout/h1
=== PAUSE TestIssue4191_InfiniteGetTimeout/h1
=== CONT  TestIssue4191_InfiniteGetTimeout/h1
panic: test timed out after 3m0s
running tests:
	TestIssue4191_InfiniteGetTimeout/h1 (2m4s)

goroutine 15284 gp=0x2265a40 m=0 mp=0x714160 [running]:
panic({0x4fe60, 0x19520c0})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:779 +0x1f fp=0x23e1f00 sp=0x23e1e58 pc=0x1293001f
...
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa fp=0x21c7f60 sp=0x21c7f10 pc=0x344a000a
testing.tRunner(0x2847860, 0x201e900)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd fp=0x21c7fc8 sp=0x21c7f60 pc=0x1b1f000d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x2 fp=0x21c7fe0 sp=0x21c7fc8 pc=0x1b250002
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x21c7fe8 sp=0x21c7fe0 pc=0x15580001
created by testing.(*T).Run in goroutine 1251
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43

— watchflakes

[gopherbot]

Change https://go.dev/cl/566175 mentions this issue: [release-branch.go1.22] net: work around runtime scheduler starvation on js and wasip1