net/http: unflake TestTimeoutHandlerSuperfluousLogs
Uses 2 channels to synchronize that test, because
relying on sleeps creates flaky behavior, thus:
a) 1 buffered channel to send back the last spurious line
without having to reason about "happens before" behavior
a) 1 buffered channel at the end of the handler; it'll
be controlled by whether we expect to timeout or not,
but will always be closed when the test ends
Fixes #35051
Change-Id: Iff735aa8d1ed9de8d92b792374ec161cc0a72798
Reviewed-on: https://go-review.googlesource.com/c/go/+/208477
Run-TryBot: Emmanuel Odeke <emm.odeke@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Bryan C. Mills <bcmills@google.com>
diff --git a/src/net/http/serve_test.go b/src/net/http/serve_test.go
index 1a690ef..63ae0fe 100644
--- a/src/net/http/serve_test.go
+++ b/src/net/http/serve_test.go
@@ -6306,6 +6306,10 @@
// Issue 30803: ensure that TimeoutHandler logs spurious
// WriteHeader calls, for consistency with other Handlers.
func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
+ if testing.Short() {
+ t.Skip("skipping in short mode")
+ }
+
setParallel(t)
defer afterTest(t)
@@ -6314,29 +6318,30 @@
testFuncName := runtime.FuncForPC(pc).Name()
timeoutMsg := "timed out here!"
- maxTimeout := 200 * time.Millisecond
tests := []struct {
- name string
- sleepTime time.Duration
- wantResp string
+ name string
+ mustTimeout bool
+ wantResp string
}{
{
- name: "return before timeout",
- sleepTime: 0,
- wantResp: "HTTP/1.1 404 Not Found\r\nContent-Length: 0\r\n\r\n",
+ name: "return before timeout",
+ wantResp: "HTTP/1.1 404 Not Found\r\nContent-Length: 0\r\n\r\n",
},
{
- name: "return after timeout",
- sleepTime: maxTimeout * 2,
+ name: "return after timeout",
+ mustTimeout: true,
wantResp: fmt.Sprintf("HTTP/1.1 503 Service Unavailable\r\nContent-Length: %d\r\n\r\n%s",
len(timeoutMsg), timeoutMsg),
},
}
for _, tt := range tests {
+ tt := tt
t.Run(tt.name, func(t *testing.T) {
- var lastSpuriousLine int32
+ exitHandler := make(chan bool, 1)
+ defer close(exitHandler)
+ lastLine := make(chan int, 1)
sh := HandlerFunc(func(w ResponseWriter, r *Request) {
w.WriteHeader(404)
@@ -6344,14 +6349,23 @@
w.WriteHeader(404)
w.WriteHeader(404)
_, _, line, _ := runtime.Caller(0)
- atomic.StoreInt32(&lastSpuriousLine, int32(line))
-
- <-time.After(tt.sleepTime)
+ lastLine <- line
+ <-exitHandler
})
+ if !tt.mustTimeout {
+ exitHandler <- true
+ }
+
logBuf := new(bytes.Buffer)
srvLog := log.New(logBuf, "", 0)
- th := TimeoutHandler(sh, maxTimeout, timeoutMsg)
+ // When expecting to timeout, we'll keep the duration short.
+ dur := 20 * time.Millisecond
+ if !tt.mustTimeout {
+ // Otherwise, make it arbitrarily long to reduce the risk of flakes.
+ dur = 10 * time.Second
+ }
+ th := TimeoutHandler(sh, dur, timeoutMsg)
cst := newClientServerTest(t, h1Mode /* the test is protocol-agnostic */, th, optWithServerLog(srvLog))
defer cst.close()
@@ -6379,10 +6393,12 @@
t.Fatalf("Server logs count mismatch\ngot %d, want %d\n\nGot\n%s\n", g, w, blob)
}
+ lastSpuriousLine := <-lastLine
+ firstSpuriousLine := lastSpuriousLine - 3
// Now ensure that the regexes match exactly.
// "http: superfluous response.WriteHeader call from <fn>.func\d.\d (<curFile>:lastSpuriousLine-[1, 3]"
for i, logEntry := range logEntries {
- wantLine := atomic.LoadInt32(&lastSpuriousLine) - 3 + int32(i)
+ wantLine := firstSpuriousLine + i
pat := fmt.Sprintf("^http: superfluous response.WriteHeader call from %s.func\\d+.\\d+ \\(%s:%d\\)$",
testFuncName, curFileBaseName, wantLine)
re := regexp.MustCompile(pat)
