Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

net/http: timeout in TestIssue4191_InfiniteGetTimeout on wasip1/wasm #65177

Closed
bcmills opened this issue Jan 19, 2024 · 6 comments
Closed

net/http: timeout in TestIssue4191_InfiniteGetTimeout on wasip1/wasm #65177

bcmills opened this issue Jan 19, 2024 · 6 comments
Assignees
@bcmills
Labels
arch-wasm WebAssembly issues FixPending Issues that have a fix which has not yet been reviewed or submitted. NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.23

Comments

@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2024 •
edited 

#!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 bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. arch-wasm WebAssembly issues labels Jan 19, 2024
@bcmills bcmills added this to the Backlog milestone Jan 19, 2024
@bcmills bcmills mentioned this issue Jan 19, 2024
Open
@bcmills
Copy link
Contributor Author

bcmills commented Jan 19, 2024

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
Copy link
Contributor Author

bcmills commented Jan 19, 2024

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.

@bcmills bcmills added NeedsFix The path to resolution is known, but the work has not been done. FixPending Issues that have a fix which has not yet been reviewed or submitted. labels Jan 19, 2024
@bcmills bcmills self-assigned this Jan 19, 2024
@gopherbot gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 19, 2024
@bcmills bcmills modified the milestones: Backlog, Go1.22 Jan 19, 2024
@gopherbot
Copy link

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

@bcmills bcmills mentioned this issue Jan 19, 2024
Open
@gopherbot
Copy link

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

@dmitshur dmitshur modified the milestones: Go1.22, Go1.23 Jan 22, 2024
@gopherbot
Copy link

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

ezz-no pushed a commit to ezz-no/go-ezzno that referenced this issue Feb 18, 2024
@ezz-no
net: work around runtime scheduler starvation on js and wasip1
ea689c7 
Fixes golang#65177.
Updates golang#65178.
Updates golang#64321.

Change-Id: I698fd3b688c7dfbde692eb7c29cbdafc89e7ca32
Cq-Include-Trybots: luci.golang.try:gotip-js-wasm,gotip-wasip1-wasm_wasmtime,gotip-wasip1-wasm_wazero
Reviewed-on: https://go-review.googlesource.com/c/go/+/557037
Auto-Submit: Bryan Mills <bcmills@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Damien Neil <dneil@google.com>
@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Feb 28, 2024
@cagedmantis
[release-branch.go1.22] net: work around runtime scheduler starvation…
f73eba7 
… on js and wasip1

For #65883.
Updates #65177.
Updates #65178.
Updates #64321.

Change-Id: I698fd3b688c7dfbde692eb7c29cbdafc89e7ca32
Cq-Include-Trybots: luci.golang.try:go1.22-js-wasm,go1.22-wasip1-wasm_wasmtime,go1.22-wasip1-wasm_wazero
Reviewed-on: https://go-review.googlesource.com/c/go/+/557037
Auto-Submit: Bryan Mills <bcmills@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Damien Neil <dneil@google.com>
(cherry picked from commit f19f31f)
Reviewed-on: https://go-review.googlesource.com/c/go/+/566175
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
bradfitz pushed a commit to tailscale/go that referenced this issue Mar 5, 2024
@bradfitz
[release-branch.go1.22] net: work around runtime scheduler starvation…
5249ed6 
… on js and wasip1

For golang#65883.
Updates golang#65177.
Updates golang#65178.
Updates golang#64321.

Change-Id: I698fd3b688c7dfbde692eb7c29cbdafc89e7ca32
Cq-Include-Trybots: luci.golang.try:go1.22-js-wasm,go1.22-wasip1-wasm_wasmtime,go1.22-wasip1-wasm_wazero
Reviewed-on: https://go-review.googlesource.com/c/go/+/557037
Auto-Submit: Bryan Mills <bcmills@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Damien Neil <dneil@google.com>
(cherry picked from commit f19f31f)
Reviewed-on: https://go-review.googlesource.com/c/go/+/566175
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
romaindoumenc pushed a commit to TroutSoftware/go that referenced this issue Mar 6, 2024
@romaindoumenc
[release-branch.go1.22] net: work around runtime scheduler starvation…
7880412 
… on js and wasip1

For golang#65883.
Updates golang#65177.
Updates golang#65178.
Updates golang#64321.

Change-Id: I698fd3b688c7dfbde692eb7c29cbdafc89e7ca32
Cq-Include-Trybots: luci.golang.try:go1.22-js-wasm,go1.22-wasip1-wasm_wasmtime,go1.22-wasip1-wasm_wazero
Reviewed-on: https://go-review.googlesource.com/c/go/+/557037
Auto-Submit: Bryan Mills <bcmills@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Damien Neil <dneil@google.com>
(cherry picked from commit f19f31f)
Reviewed-on: https://go-review.googlesource.com/c/go/+/566175
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bcmills bcmills

Labels
arch-wasm WebAssembly issues FixPending Issues that have a fix which has not yet been reviewed or submitted. NeedsFix The path to resolution is known, but the work has not been done.
Projects
Test Flakes
Status: Done
Milestone
Go1.23
Development

No branches or pull requests
3 participants
@dmitshur @bcmills @gopherbot