net/http: apparent TestServerAllowsBlockingRemoteAddr flakes due to hard-coded timeouts

[bcmills]

#!watchflakes
post <- pkg == "net/http" && (test == "TestServerAllowsBlockingRemoteAddr" || `^\s+TestServerAllowsBlockingRemoteAddr \(\d+m`) && (`panic: test timed out` || `context deadline exceeded`)

2019-12-16T20:38:31-f7f9866/plan9-386-0intro
2019-06-12T14:58:18-65f53da/plan9-amd64-9front

--- FAIL: TestServerAllowsBlockingRemoteAddr (1.08s)
    serve_test.go:1300: Request 1: Get "http://127.0.0.1:55517": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
    serve_test.go:1349: response 1 addr = ""; want "RA:21.21.21.21:21"
http.test 1018696: warning: process exceeds 100 file descriptors
FAIL
FAIL	net/http	114.189s

As far as I can tell, the root cause is the hard-coded time.Second here:

go/src/net/http/serve_test.go

Lines 1326 to 1330 in 931fe39

	select {
	case conn2 = <-conns:
	case <-time.After(time.Second):
	t.Fatal("Second Accept didn't happen")
	}

It's not obvious to me why a timeout is needed there at all. If the test deadlocks, we presumably want a goroutine dump anyway.

CC @bradfitz @0intro @fhs

[bcmills]

That's the regression test for #12943.

[howjmay]

Is this one still one still open

[gopherbot]

Sorry, but there were parse errors in the watch flakes script.
The script I found was:

#!watchflakes
pkg == "net/http" && test == "TestServerAllowsBlockingRemoteAddr" && (`panic: test timed out` || `context deadline exceeded`)

And the problems were:

script:2.5: unexpected ==

See https://go.dev/wiki/Watchflakes for details.

— watchflakes

[bcmills]

The failure log linked in #57995 (comment) matches this issue; I'm not sure why watchflakes isn't posting it here.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && (test == "TestServerAllowsBlockingRemoteAddr" || `^\s+TestServerAllowsBlockingRemoteAddr \(\d+m`) && (`panic: test timed out` || `context deadline exceeded`)

2023-01-17 18:12 dragonfly-amd64-622 go@c0799f70 net/http (log)

1 second passes in backend, proxygone= false
panic: test timed out after 3m0s
running tests:
	TestServerAllowsBlockingRemoteAddr (2m59s)
	TestServerAllowsBlockingRemoteAddr/h1 (2m54s)

goroutine 21276 [running]:
panic({0x848280, 0xc00018a8b0})
	/tmp/workdir/go/src/runtime/panic.go:987 +0x3bb fp=0xc000653f10 sp=0xc000653e50 pc=0x436b7b
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2241 +0x3b9 fp=0xc000653fe0 sp=0xc000653f10 pc=0x4fd339
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000653fe8 sp=0xc000653fe0 pc=0x46b201
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x32

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && (test == "TestServerAllowsBlockingRemoteAddr" || `^\s+TestServerAllowsBlockingRemoteAddr \(\d+m`) && (`panic: test timed out` || `context deadline exceeded`)

2023-02-24 19:16 dragonfly-amd64-622 go@8e5f56a2 net/http (log)

panic: test timed out after 3m0s
running tests:
	TestServerAllowsBlockingRemoteAddr (3m0s)
	TestServerAllowsBlockingRemoteAddr/h1 (2m57s)

goroutine 21822 [running]:
panic({0x821680?, 0xc00108c720?})
	/tmp/workdir/go/src/runtime/panic.go:1015 +0x3ac fp=0xc000627f10 sp=0xc000627e60 pc=0x43564c
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2244 +0x3b4 fp=0xc000627fe0 sp=0xc000627f10 pc=0x4f7554
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000627fe8 sp=0xc000627fe0 pc=0x4693c1
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x2d

— watchflakes

[bcmills]

Interesting! Those dragonfly failures look like actual deadlocks, not just spurious timeouts.

[bcmills]

Nope, it is still the same spurious timeout:
https://cs.opensource.google/go/go/+/master:src/net/http/serve_test.go;l=1362;drc=133e0bca0be23980604ee98589ddcacdb1262afd

It's just manifesting as a deadlock due to some synchronous cleanup code.