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: unexplained timeout on wasip1/wasm #64321

Open
gopherbot opened this issue Nov 21, 2023 · 12 comments
Open

net/http: unexplained timeout on wasip1/wasm #64321

gopherbot opened this issue Nov 21, 2023 · 12 comments
Labels
arch-wasm WebAssembly issues NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone
Backlog

Comments

@gopherbot
Copy link

gopherbot commented Nov 21, 2023 •
edited by bcmills 

#!watchflakes
default <- goarch == "wasm" && pkg == "net/http" && log ~ `panic: test timed out`

Issue created automatically to collect these failures.

Example (log):

panic: test timed out after 3m0s
running tests:
	TestClientRedirectNoLocation (2m49s)
	TestClientRedirectNoLocation/h1 (2m20s)
	TestClientRedirectNoLocation/h2 (2m20s)
	TestConnContextNotModifyingAllContexts (2m48s)
	TestContentEncodingNoSniffing (2m48s)
	TestContentTypeWithVariousSources (2m48s)
	TestDisableContentLength (2m48s)
	TestDisableKeepAliveUpgrade (2m48s)
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x21ddf60 sp=0x21ddf10 pc=0x3407000a
testing.tRunner(0x22e7380, 0x1ad8900)
	/workdir/go/src/testing/testing.go:1682 +0xd fp=0x21ddfc8 sp=0x21ddf60 pc=0x1add000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1735 +0x2 fp=0x21ddfe0 sp=0x21ddfc8 pc=0x1ae30002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x21ddfe8 sp=0x21ddfe0 pc=0x151b0001
created by testing.(*T).Run in goroutine 1250
	/workdir/go/src/testing/testing.go:1735 +0x43

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 21, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "net/http" && test == ""
2023-11-21 21:28 wasip1-wasm-wazero go@d1dcffdb net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestClientRedirectNoLocation (2m49s)
	TestClientRedirectNoLocation/h1 (2m20s)
	TestClientRedirectNoLocation/h2 (2m20s)
	TestConnContextNotModifyingAllContexts (2m48s)
	TestContentEncodingNoSniffing (2m48s)
	TestContentTypeWithVariousSources (2m48s)
	TestDisableContentLength (2m48s)
	TestDisableKeepAliveUpgrade (2m48s)
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x21ddf60 sp=0x21ddf10 pc=0x3407000a
testing.tRunner(0x22e7380, 0x1ad8900)
	/workdir/go/src/testing/testing.go:1682 +0xd fp=0x21ddfc8 sp=0x21ddf60 pc=0x1add000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1735 +0x2 fp=0x21ddfe0 sp=0x21ddfc8 pc=0x1ae30002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x21ddfe8 sp=0x21ddfe0 pc=0x151b0001
created by testing.(*T).Run in goroutine 1250
	/workdir/go/src/testing/testing.go:1735 +0x43

— watchflakes

@bcmills bcmills added the arch-wasm WebAssembly issues label Nov 27, 2023
@bcmills bcmills added this to the Backlog milestone Nov 27, 2023
@bcmills
Copy link
Contributor

bcmills commented Nov 27, 2023

This may be a bug in https://go.dev/cl/526117. I will investigate.

(CC @golang/wasm)

@bcmills bcmills self-assigned this Nov 27, 2023
@bcmills
Copy link
Contributor

bcmills commented Nov 27, 2023

Note that the actual interestingly-running test here is:

	TestTransportExpect100Continue/h1 (2s)

(Filed #64404 for the unclear logging.)

@bcmills bcmills changed the title net/http: unrecognized failures net/http: unexplained timeout on wasip1/wasm Nov 27, 2023
@bcmills
Copy link
Contributor

bcmills commented Nov 27, 2023 •
edited

Given that there was a test that had only been running for 2s, it seems like the test must have hung somewhere else for a long time. Unassigning to collect more data and look for a pattern.

(CC @neild)

@bcmills bcmills removed their assignment Nov 27, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- goarch == "wasm" && pkg == "net/http" && log ~ `panic: test timed out`
2023-12-07 19:52 gotip-wasip1-wasm_wazero go@e1c0349a 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 (2m4s)

goroutine 15243 gp=0x1a94380 m=0 mp=0x7130a0 [running]:
panic({0x4fe60, 0x4ee5780})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:779 +0x1f fp=0x23e7f00 sp=0x23e7e58 pc=0x1293001f
...
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa fp=0x21c5f60 sp=0x21c5f10 pc=0x3449000a
testing.tRunner(0x2843860, 0x18ca840)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd fp=0x21c5fc8 sp=0x21c5f60 pc=0x1b1f000d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x2 fp=0x21c5fe0 sp=0x21c5fc8 pc=0x1b250002
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x21c5fe8 sp=0x21c5fe0 pc=0x15580001
created by testing.(*T).Run in goroutine 1250
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43
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

@bcmills bcmills mentioned this issue Jan 19, 2024
Closed
@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2024

The above seems like a different failure mode; filed as #65177.

@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
@bcmills bcmills modified the milestones: Backlog, Go1.22 Jan 19, 2024
@bcmills bcmills removed 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 modified the milestones: Go1.22, Backlog Jan 19, 2024
@bcmills bcmills removed their assignment Jan 19, 2024
@gopherbot
Copy link
Author

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

@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2024

This may or may not be fixed by https://go.dev/cl/557037.

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jan 19, 2024
gopherbot pushed a commit that referenced this issue Jan 19, 2024
@gopherbot
net: work around runtime scheduler starvation on js and wasip1
f19f31f 
Fixes #65177.
Updates #65178.
Updates #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
Author

Found new dashboard test flakes for:

#!watchflakes
default <- goarch == "wasm" && pkg == "net/http" && log ~ `panic: test timed out`
2024-01-29 22:55 js-wasm-node18 go@0c64be46 net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m52s)

goroutine 51007 gp=0x1a45a40 m=0 mp=0x719e20 [running]:
panic({0x50640, 0x18e97f0})
	/workdir/go/src/runtime/panic.go:768 +0x1f fp=0x1b5df00 sp=0x1b5de58 pc=0x127b001f
testing.(*M).startAlarm.func1()
	/workdir/go/src/testing/testing.go:2366 +0x44 fp=0x1b5dfe0 sp=0x1b5df00 pc=0x1b2f0044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x2b41760 sp=0x2b41710 pc=0x344f000a
testing.tRunner(0x2b70340, 0x2b51800)
	/workdir/go/src/testing/testing.go:1689 +0xd fp=0x2b417c8 sp=0x2b41760 pc=0x1b16000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1742 +0x2 fp=0x2b417e0 sp=0x2b417c8 pc=0x1b1c0002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x2b417e8 sp=0x2b417e0 pc=0x153f0001
created by testing.(*T).Run in goroutine 1141
	/workdir/go/src/testing/testing.go:1742 +0x43
2024-01-29 22:55 wasip1-wasm-wazero go@0c64be46 net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m41s)

goroutine 18132 gp=0x1ac61c0 m=0 mp=0x70e180 [running]:
panic({0x4fe80, 0x198a7f0})
	/workdir/go/src/runtime/panic.go:768 +0x1f fp=0x1a31f00 sp=0x1a31e58 pc=0x1293001f
testing.(*M).startAlarm.func1()
	/workdir/go/src/testing/testing.go:2366 +0x44 fp=0x1a31fe0 sp=0x1a31f00 pc=0x1b380044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x2b9af60 sp=0x2b9af10 pc=0x344a000a
testing.tRunner(0x2bec340, 0x2bbd020)
	/workdir/go/src/testing/testing.go:1689 +0xd fp=0x2b9afc8 sp=0x2b9af60 pc=0x1b1f000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1742 +0x2 fp=0x2b9afe0 sp=0x2b9afc8 pc=0x1b250002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x2b9afe8 sp=0x2b9afe0 pc=0x15580001
created by testing.(*T).Run in goroutine 1135
	/workdir/go/src/testing/testing.go:1742 +0x43
2024-01-30 00:04 js-wasm-node18 go@f96d9a64 net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m52s)

goroutine 50509 gp=0x19c9a40 m=0 mp=0x719e20 [running]:
panic({0x50640, 0x193f0a0})
	/workdir/go/src/runtime/panic.go:768 +0x1f fp=0x1ab3f00 sp=0x1ab3e58 pc=0x127b001f
testing.(*M).startAlarm.func1()
	/workdir/go/src/testing/testing.go:2366 +0x44 fp=0x1ab3fe0 sp=0x1ab3f00 pc=0x1b300044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x2a9f760 sp=0x2a9f710 pc=0x3450000a
testing.tRunner(0x2ae8340, 0x2ac1770)
	/workdir/go/src/testing/testing.go:1689 +0xd fp=0x2a9f7c8 sp=0x2a9f760 pc=0x1b17000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1742 +0x2 fp=0x2a9f7e0 sp=0x2a9f7c8 pc=0x1b1d0002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x2a9f7e8 sp=0x2a9f7e0 pc=0x15400001
created by testing.(*T).Run in goroutine 1139
	/workdir/go/src/testing/testing.go:1742 +0x43
2024-01-30 00:04 wasip1-wasm-wazero go@f96d9a64 net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m41s)

goroutine 18632 gp=0x19af500 m=0 mp=0x70e180 [running]:
panic({0x4fea0, 0x32353d0})
	/workdir/go/src/runtime/panic.go:768 +0x1f fp=0x2066f00 sp=0x2066e58 pc=0x1293001f
testing.(*M).startAlarm.func1()
	/workdir/go/src/testing/testing.go:2366 +0x44 fp=0x2066fe0 sp=0x2066f00 pc=0x1b390044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/workdir/go/src/net/http/clientserver_test.go:85 +0xa fp=0x2bd5f60 sp=0x2bd5f10 pc=0x344b000a
testing.tRunner(0x2bf6340, 0x2be9260)
	/workdir/go/src/testing/testing.go:1689 +0xd fp=0x2bd5fc8 sp=0x2bd5f60 pc=0x1b20000d
testing.(*T).Run.gowrap1()
	/workdir/go/src/testing/testing.go:1742 +0x2 fp=0x2bd5fe0 sp=0x2bd5fc8 pc=0x1b260002
runtime.goexit({})
	/workdir/go/src/runtime/asm_wasm.s:434 +0x1 fp=0x2bd5fe8 sp=0x2bd5fe0 pc=0x15590001
created by testing.(*T).Run in goroutine 1139
	/workdir/go/src/testing/testing.go:1742 +0x43

— watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
default <- goarch == "wasm" && pkg == "net/http" && log ~ `panic: test timed out`
2024-01-29 22:55 gotip-wasip1-wasm_wasmtime go@0c64be46 net/http.TestServerWriteTimeout [ABORT] (log) 
=== RUN   TestServerWriteTimeout/h2
=== PAUSE TestServerWriteTimeout/h2
=== CONT  TestServerWriteTimeout/h2
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:563: read tcp 127.0.0.1:562->127.0.0.1:563: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:564: read tcp 127.0.0.1:562->127.0.0.1:564: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:565: read tcp 127.0.0.1:562->127.0.0.1:565: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:566: read tcp 127.0.0.1:562->127.0.0.1:566: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:567: read tcp 127.0.0.1:562->127.0.0.1:567: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:568: read tcp 127.0.0.1:562->127.0.0.1:568: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:569: read tcp 127.0.0.1:562->127.0.0.1:569: i/o timeout
...
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m30s)

goroutine 42204 [running]:
testing.(*M).startAlarm.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x44
created by time.goFunc
	/home/swarming/.swarming/w/ir/x/w/goroot/src/time/sleep.go:177 +0x5

...
testing.(*T).Parallel(0x2b7e340)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1484 +0x20
net/http_test.setParallel(0x2b7e340)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/main_test.go:95 +0x20
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa
testing.tRunner(0x2b7e340, 0x2b7dbc0)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd
created by testing.(*T).Run in goroutine 1139
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43
2024-01-29 22:55 gotip-wasip1-wasm_wazero go@0c64be46 net/http.TestServerWriteTimeout [ABORT] (log) 
=== RUN   TestServerWriteTimeout/h2
=== PAUSE TestServerWriteTimeout/h2
=== CONT  TestServerWriteTimeout/h2
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:563: read tcp 127.0.0.1:562->127.0.0.1:563: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:564: read tcp 127.0.0.1:562->127.0.0.1:564: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:565: read tcp 127.0.0.1:562->127.0.0.1:565: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:566: read tcp 127.0.0.1:562->127.0.0.1:566: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:567: read tcp 127.0.0.1:562->127.0.0.1:567: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:568: read tcp 127.0.0.1:562->127.0.0.1:568: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:569: read tcp 127.0.0.1:562->127.0.0.1:569: i/o timeout
...
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m35s)

goroutine 18497 gp=0x1ac76c0 m=0 mp=0x712180 [running]:
panic({0x4fe80, 0x18374b0})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:768 +0x1f fp=0x2254f00 sp=0x2254e58 pc=0x1293001f
testing.(*M).startAlarm.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x44 fp=0x2254fe0 sp=0x2254f00 pc=0x1b380044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa fp=0x2b70f60 sp=0x2b70f10 pc=0x344a000a
testing.tRunner(0x3034340, 0x300d0e0)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd fp=0x2b70fc8 sp=0x2b70f60 pc=0x1b1f000d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x2 fp=0x2b70fe0 sp=0x2b70fc8 pc=0x1b250002
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x2b70fe8 sp=0x2b70fe0 pc=0x15580001
created by testing.(*T).Run in goroutine 1140
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43
2024-01-30 00:04 gotip-wasip1-wasm_wasmtime go@f96d9a64 net/http.TestServerWriteTimeout [ABORT] (log) 
=== RUN   TestServerWriteTimeout/h2
=== PAUSE TestServerWriteTimeout/h2
=== CONT  TestServerWriteTimeout/h2
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:563: read tcp 127.0.0.1:562->127.0.0.1:563: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:564: read tcp 127.0.0.1:562->127.0.0.1:564: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:565: read tcp 127.0.0.1:562->127.0.0.1:565: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:566: read tcp 127.0.0.1:562->127.0.0.1:566: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:567: read tcp 127.0.0.1:562->127.0.0.1:567: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:568: read tcp 127.0.0.1:562->127.0.0.1:568: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:569: read tcp 127.0.0.1:562->127.0.0.1:569: i/o timeout
...
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m30s)

goroutine 42091 [running]:
testing.(*M).startAlarm.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x44
created by time.goFunc
	/home/swarming/.swarming/w/ir/x/w/goroot/src/time/sleep.go:177 +0x5

...
testing.(*T).Parallel(0x2b76340)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1484 +0x20
net/http_test.setParallel(0x2b76340)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/main_test.go:95 +0x20
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa
testing.tRunner(0x2b76340, 0x2b5ea50)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd
created by testing.(*T).Run in goroutine 1140
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43
2024-01-30 00:04 gotip-wasip1-wasm_wazero go@f96d9a64 net/http.TestServerWriteTimeout [ABORT] (log) 
=== RUN   TestServerWriteTimeout/h2
=== PAUSE TestServerWriteTimeout/h2
=== CONT  TestServerWriteTimeout/h2
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:563: read tcp 127.0.0.1:562->127.0.0.1:563: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:564: read tcp 127.0.0.1:562->127.0.0.1:564: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:565: read tcp 127.0.0.1:562->127.0.0.1:565: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:566: read tcp 127.0.0.1:562->127.0.0.1:566: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:567: read tcp 127.0.0.1:562->127.0.0.1:567: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:568: read tcp 127.0.0.1:562->127.0.0.1:568: i/o timeout
    clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:569: read tcp 127.0.0.1:562->127.0.0.1:569: i/o timeout
...
panic: test timed out after 3m0s
running tests:
	TestServerWriteTimeout/h2 (2m37s)

goroutine 18791 gp=0x1afca80 m=0 mp=0x713180 [running]:
panic({0x4fea0, 0x18f5b70})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:768 +0x1f fp=0x1b22f00 sp=0x1b22e58 pc=0x1293001f
testing.(*M).startAlarm.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x44 fp=0x1b22fe0 sp=0x1b22f00 pc=0x1b390044
runtime.goexit({})
...
net/http_test.run[...].func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/net/http/clientserver_test.go:85 +0xa fp=0x30caf60 sp=0x30caf10 pc=0x344b000a
testing.tRunner(0x2bf6340, 0x2bf0de0)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1689 +0xd fp=0x30cafc8 sp=0x30caf60 pc=0x1b20000d
testing.(*T).Run.gowrap1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x2 fp=0x30cafe0 sp=0x30cafc8 pc=0x1b260002
runtime.goexit({})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_wasm.s:434 +0x1 fp=0x30cafe8 sp=0x30cafe0 pc=0x15590001
created by testing.(*T).Run in goroutine 1136
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x43

— watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
default <- goarch == "wasm" && pkg == "net/http" && log ~ `panic: test timed out`
2024-01-04 20:40 go1.22-wasip1-wasm_wazero release-branch.go1.22@1e07c144 net/http.TestChunkedNoContent [ABORT] (log) 
=== RUN   TestChunkedNoContent
=== PAUSE TestChunkedNoContent
=== CONT  TestChunkedNoContent

— 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
Author

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
No one assigned
Labels
arch-wasm WebAssembly issues NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
Test Flakes
Status: Active
Milestone
Backlog
Development

No branches or pull requests
2 participants
@bcmills @gopherbot