net/http: failures ending in "Timeout." in testTransportAndServerSharedBodyRace #49336

bcmills · 2021-11-04T02:44:13Z

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

These failures are rare but ongoing.

2021/11/03 22:22:26 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0x14000528240 127.0.0.1:59158 in state active
1 second passes in backend, proxygone= false
goroutine 10950 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/buildlet/go/src/net/http/serve_test.go:3959 +0x54
created by time.goFunc
	/tmp/buildlet/go/src/time/sleep.go:176 +0x3c
…
2021/11/03 22:22:28 Timeout.
FAIL	net/http	10.800s

greplogs --dashboard -md -l -e $\?ms$testTransportAndServerSharedBodyRace.\*Timeout\\.\$

2021-11-04T02:12:52-bd49a99/darwin-arm64-11_0-toothrot
2021-10-01T14:30:33-8d494b0/linux-riscv64-jsing
2021-09-28T18:58:50-9c43872/linux-riscv64-jsing
2021-09-02T09:25:10-6705191/linux-riscv64-jsing
2021-08-21T11:23:14-8fff20f/netbsd-arm-bsiegert
2020-10-20T17:53:02-10a1a1a/darwin-amd64-race
2020-10-01T19:13:03-5756b35/darwin-amd64-race
2020-08-24T06:03:06-ffbd852/darwin-amd64-nocgo
2020-04-28T19:49:53-71e0cd8/darwin-amd64-race

CC @neild

The text was updated successfully, but these errors were encountered:

neild · 2021-11-04T17:12:52Z

Might just be slow/overloaded machines taking more than 5s to Close a server? Perhaps we should just triple the timeout and see if the problem goes away.

bcmills · 2021-11-04T17:27:18Z

I'll be pretty surprised if that fixes it, but it at least seems worth trying!

bcmills · 2023-01-06T20:05:45Z

watchflakes found another one of these in #57600 (CC @neild).

gopherbot · 2023-01-16T21:45:40Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2022-11-21 16:19 openbsd-386-72 go@d7812ab3 net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2022/12/28 21:07:52 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x58c32600 127.0.0.1:34590 in state active
1 second passes in backend, proxygone= false
2022/12/28 21:07:52 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x58c33a00 127.0.0.1:9189 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 23258 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4041 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-01-25T16:37:05Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-01-17 16:22 openbsd-386-72 go@f375b305 net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/01/17 08:45:36 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x6d62c000 127.0.0.1:15140 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 22988 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4041 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-02-02T19:56:49Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-01-25 21:12 openbsd-386-72 go@3d49b683 net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/01/25 13:33:50 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x64b94000 127.0.0.1:26162 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 22352 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4041 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-02-24T16:36:47Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-02-04 07:03 openbsd-386-72 go@4636c57f net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/02/03 23:15:08 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x58bba400 127.0.0.1:19717 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 21913 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4037 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

2023-02-15 21:45 darwin-amd64-10_15 go@965e9ba0 net/http (log)

2023/02/16 02:53:55 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0xc0000a2070 127.0.0.1:50502 in state active
goroutine 10064 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/buildlet/go/src/net/http/serve_test.go:4041 +0x54
created by time.goFunc
	/tmp/buildlet/go/src/time/sleep.go:176 +0x32

2023-02-23 22:08 openbsd-386-72 go@f60a2a9c net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/02/23 14:20:37 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x58d54600 127.0.0.1:35101 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 20755 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4037 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-02-28T03:23:15Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-01-20 01:06 openbsd-386-72 go@045b33ec net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/01/19 17:29:34 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x60c52000 127.0.0.1:42535 in state active
2023/01/19 17:29:34 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x602d4400 127.0.0.1:1703 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 23362 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4041 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-03-08T18:18:16Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-02-28 17:47 openbsd-386-72 go@eee2697c net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/02/28 10:02:33 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x61260a00 127.0.0.1:13799 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 21618 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4037 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

gopherbot · 2023-03-13T20:45:29Z

Change https://go.dev/cl/476035 mentions this issue: net/http: remove more arbitrary timeouts from server tests

This change eliminates the easy, arbitrary timouts that should never happen. It leaves in place a couple of more complicated ones that will probably need retry loops for robustness. For #49336. For #36179. Change-Id: I657ef223a66461413a915da5ce9150f49acec04a Reviewed-on: https://go-review.googlesource.com/c/go/+/476035 Run-TryBot: Bryan Mills <bcmills@google.com> Auto-Submit: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Damien Neil <dneil@google.com>

bcmills · 2023-03-13T21:24:12Z

This particular failure mode should be fixed by CL 476035. It is possible that that will uncover further failure modes, but watchflakes can file issues for those if they occur.

gopherbot · 2023-03-14T16:07:35Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-03-13 16:58 darwin-amd64-11_0 go@bcd8161f net/http.TestOmitHTTP2Vet (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 10949 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/buildlet/go/src/net/http/serve_test.go:4031 +0x50
created by time.goFunc
...
	/tmp/buildlet/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0xc001d7c580)
	/tmp/buildlet/go/src/os/exec/exec.go:890 +0x45
os/exec.(*Cmd).Run(0xc000028540?)
	/tmp/buildlet/go/src/os/exec/exec.go:590 +0x2d
os/exec.(*Cmd).CombinedOutput(0xc001d7c580)
	/tmp/buildlet/go/src/os/exec/exec.go:1005 +0x94
net/http.TestOmitHTTP2Vet(0xc000240ea0)
	/tmp/buildlet/go/src/net/http/http_test.go:133 +0xa5
testing.tRunner(0xc000240ea0, 0x14ff358)

— watchflakes

gopherbot · 2023-10-10T18:10:21Z

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && `testTransportAndServerSharedBodyRace` && `Timeout\.$`

2023-10-10 16:18 openbsd-386-72 go@e175f27f net/http (log)

1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2023/10/10 10:35:10 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *tls.Conn 0x6c5f4200 127.0.0.1:43248 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 21399 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
	/tmp/workdir/go/src/net/http/serve_test.go:4041 +0x6c
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x29

— watchflakes

bcmills · 2023-10-11T16:05:12Z

e175f27f is on release-branch.go1.20 (#59483)

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 4, 2021

bcmills added this to the Backlog milestone Nov 4, 2021

bcmills mentioned this issue Jan 6, 2023

net/http: unrecognized failures #57600

Closed

bcmills mentioned this issue Jan 26, 2023

net/http: apparent deadlock in TestTransportAndServerSharedBodyRace_h1 on OpenBSD #36161

Closed

bcmills mentioned this issue Feb 8, 2023

net/http: TestTransportAndServerSharedBodyRace failures with Proxy copy error #58398

Closed

bcmills closed this as completed Mar 13, 2023

bcmills added the Testing An issue that has been verified to require only test changes, not just a test failure. label Mar 13, 2023

bcmills self-assigned this Mar 13, 2023

bcmills modified the milestones: Backlog, Go1.21 Mar 13, 2023

gopherbot reopened this Oct 10, 2023

bcmills closed this as completed Oct 11, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: failures ending in "Timeout." in testTransportAndServerSharedBodyRace #49336

net/http: failures ending in "Timeout." in testTransportAndServerSharedBodyRace #49336

bcmills commented Nov 4, 2021 •

edited

neild commented Nov 4, 2021

bcmills commented Nov 4, 2021

bcmills commented Jan 6, 2023

gopherbot commented Jan 16, 2023

gopherbot commented Jan 25, 2023

gopherbot commented Feb 2, 2023

gopherbot commented Feb 24, 2023

gopherbot commented Feb 28, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 13, 2023

bcmills commented Mar 13, 2023

gopherbot commented Mar 14, 2023

gopherbot commented Oct 10, 2023

bcmills commented Oct 11, 2023

net/http: failures ending in "Timeout." in testTransportAndServerSharedBodyRace #49336

net/http: failures ending in "Timeout." in testTransportAndServerSharedBodyRace #49336

Comments

bcmills commented Nov 4, 2021 • edited

neild commented Nov 4, 2021

bcmills commented Nov 4, 2021

bcmills commented Jan 6, 2023

gopherbot commented Jan 16, 2023

gopherbot commented Jan 25, 2023

gopherbot commented Feb 2, 2023

gopherbot commented Feb 24, 2023

gopherbot commented Feb 28, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 13, 2023

bcmills commented Mar 13, 2023

gopherbot commented Mar 14, 2023

gopherbot commented Oct 10, 2023

bcmills commented Oct 11, 2023

bcmills commented Nov 4, 2021 •

edited