Thanks for the file @bcmills! Sheesh how does one then test a Timeout if 2X the requested sleep time still doesn't time out? I'll send a CL skipping that test to avoid blocking the builders.

The flake rate seems low enough that a Skip probably isn't necessary at this point.

But yeah: never underestimate the slowness of builders.

(It's a corollary of the “infinite monkeys” theorem: “Infinitely many monkeys simulating TryBot runs will eventually produce an antagonistic schedule.”)

The flake rate seems low enough that a Skip probably isn't necessary at this point.

Cool, thanks! However, this would point to being a runtime problem if the timer for the goroutine that fires insider the handler, fires earlier than the timer of the overall handler. We should investigate that angle too.

But yeah: never underestimate the slowness of builders.

(It's a corollary of the “infinite monkeys” theorem: “Infinitely many monkeys simulating TryBot runs will eventually produce an antagonistic schedule.”)

Hehe, indeed!

if the timer for the goroutine that fires insider the handler, fires earlier than the timer of the overall handler.

Note that with goroutine preemption (#24543), it is in general possible for the two timers to fire “in order”, but for the next statement(s) after the first timer to be preempted immediately and ultimately execute after the statements immediately after the second timer. (If the two goroutines don't have a “happens-before” edge, their execution order is unspecified regardless of wall time.)

freebsd-amd64-race (https://build.golang.org/log/973f4071939084efe638fa859e6473379cdbe698):

--- FAIL: TestTimeoutHandlerSuperfluousLogs (0.55s)
    --- FAIL: TestTimeoutHandlerSuperfluousLogs/return_after_timeout (0.54s)
        serve_test.go:6338: Response mismatch
            Got
            "HTTP/1.1 404 Not Found\r\nContent-Length: 0\r\n\r\n"
            
            Want
            "HTTP/1.1 503 Service Unavailable\r\nContent-Length: 15\r\n\r\ntimed out here!"
FAIL
FAIL	net/http	14.330s

2019-11-10T17:12:15-40ebcfa/solaris-amd64-oraclerel
2019-11-08T20:50:17-9e914f5/aix-ppc64
2019-11-07T20:14:02-689f6f7/freebsd-amd64-race
2019-11-07T19:20:35-ceca99b/freebsd-amd64-race
2019-11-07T19:14:27-7331708/plan9-amd64-9front
2019-11-07T14:53:38-e8f01d5/plan9-amd64-9front
2019-11-06T09:09:59-0c5d545/plan9-amd64-9front
2019-11-02T19:53:12-bdb5e9d/dragonfly-amd64
2019-11-01T14:48:28-a570fcf/plan9-386-0intro
2019-10-31T20:45:40-d6f2f83/dragonfly-amd64
2019-10-31T15:14:45-02a5502/dragonfly-amd64
2019-10-31T12:02:57-5469770/solaris-amd64-oraclerel
2019-10-31T09:49:57-1085560/dragonfly-amd64
2019-10-30T03:48:03-9e094ea/plan9-amd64-9front
2019-10-29T21:21:09-70331a3/dragonfly-amd64
2019-10-29T19:10:25-1d4369f/windows-amd64-longtest

2019-11-20T04:17:59-8c51b66/freebsd-amd64-race
2019-11-20T04:17:59-8c51b66/solaris-amd64-oraclerel
2019-11-18T14:40:07-afac2c0/freebsd-amd64-race
2019-11-15T21:04:43-440f7d6/darwin-amd64-nocgo
2019-11-15T20:56:53-4160a71/freebsd-amd64-race
2019-11-14T21:33:00-fc3eae5/dragonfly-amd64-5_6
2019-11-14T17:43:48-d3c2b1f/aix-ppc64
2019-11-13T21:24:35-718f553/aix-ppc64
2019-11-12T21:27:38-2de897f/freebsd-amd64-race
2019-11-12T01:09:31-0ee22d9/freebsd-amd64-race
2019-11-11T20:17:03-eb55a0c/darwin-amd64-10_14
2019-11-11T19:56:33-0e312f2/aix-ppc64

@odeke-em, do you plan to address this yourself?

Yes, I'll work on this tomorrow morning or later tonight. Thanks for the ping @bcmills!

I think I have 2 options here:
a) Reduce the maxTimeout to say 100 microseconds, increase sleepTime to 200 X maxTimeout -- would be odd if the scheduler doesn't hit us back after 200X the maxTimeout
b) Use faketime which by virtue is bound to have well organized/synchronized "sleeps" and the test should always pass

Despite us just only needing to ensure that that 503 is returned after the goroutine for the timer in the TimeoutHandler expires,
a) seems like the best horse in the race as it'll properly ensure that we test with common runtimes, but b) will ensure we never get flakes but also that will require us putting the test in a special file guarded with the faketime build constraint and there currently isn't any other test that does that, so perhaps I am overreacting by looking at b).

a) it is! CL coming up shortly.

Change https://golang.org/cl/208477 mentions this issue: net/http: radically change TestTimeoutHandlerSuperfluousLogs timeouts

2019-11-25T19:02:50-7adafc9/freebsd-amd64-race
2019-11-25T15:08:18-01f15b6/windows-386-2008
2019-11-22T19:01:42-c931f1b/solaris-amd64-oraclerel
2019-11-22T16:04:32-1c5bd34/darwin-amd64-nocgo

Interestingly this hasn't happened since 2019-11-25.