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 1a690efb49c0e3ccae8a382908b4122256bf5fb6..63ae0fe6d8d47fe2d990a1f6898e98a71d54238f 100644 (file)
--- a/src/net/http/serve_test.go
+++ b/src/net/http/serve_test.go
@@ -6306,6 +6306,10 @@ func testContentEncodingNoSniffing(t *testing.T, h2 bool) {
 // 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 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
        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 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
                                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 @@ func TestTimeoutHandlerSuperfluousLogs(t *testing.T) {
                                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)