From: Bryan C. Mills <bcmills@google.com>
Date: Thu, 4 Nov 2021 02:15:17 +0000 (-0400)
Subject: net/http: reduce TestClientTimeout_h{1,2} latency
X-Git-Tag: go1.18beta1~551
X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=a3f7be9b8cee00aa281a0bedeae22b4cd4bc64dd;p=gostls13.git

net/http: reduce TestClientTimeout_h{1,2} latency

The test had been setting an arbitrary 200ms timeout to allow the
server's handler to set up before timing out. That is not only
potentially flaky on slow machines, but also typically much longer
than necessary. Replace the hard-coded timeout with a much shorter
initial timeout, and use exponential backoff to lengthen it if needed.

This allows the test to be run about 20x faster in the typical case,
which may make it easier to reproduce rare failure modes by running
with a higher -count flag.

For #43120

Change-Id: I1e0d0ec99d5a107fff56e3bcc7174d686ec582d1
Reviewed-on: https://go-review.googlesource.com/c/go/+/361275
Trust: Bryan C. Mills <bcmills@google.com>
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Damien Neil <dneil@google.com>
---

diff --git a/src/net/http/client_test.go b/src/net/http/client_test.go
index e741c3746f..fb6fbe7197 100644
--- a/src/net/http/client_test.go
+++ b/src/net/http/client_test.go
@@ -1205,64 +1205,80 @@ func TestClientTimeout_h2(t *testing.T) { testClientTimeout(t, h2Mode) }
 func testClientTimeout(t *testing.T, h2 bool) {
 	setParallel(t)
 	defer afterTest(t)
-	testDone := make(chan struct{}) // closed in defer below
 
-	sawRoot := make(chan bool, 1)
-	sawSlow := make(chan bool, 1)
+	var (
+		mu           sync.Mutex
+		nonce        string // a unique per-request string
+		sawSlowNonce bool   // true if the handler saw /slow?nonce=<nonce>
+	)
 	cst := newClientServerTest(t, h2, HandlerFunc(func(w ResponseWriter, r *Request) {
+		_ = r.ParseForm()
 		if r.URL.Path == "/" {
-			sawRoot <- true
-			Redirect(w, r, "/slow", StatusFound)
+			Redirect(w, r, "/slow?nonce="+r.Form.Get("nonce"), StatusFound)
 			return
 		}
 		if r.URL.Path == "/slow" {
-			sawSlow <- true
+			mu.Lock()
+			if r.Form.Get("nonce") == nonce {
+				sawSlowNonce = true
+			} else {
+				t.Logf("mismatched nonce: received %s, want %s", r.Form.Get("nonce"), nonce)
+			}
+			mu.Unlock()
+
 			w.Write([]byte("Hello"))
 			w.(Flusher).Flush()
-			<-testDone
+			<-r.Context().Done()
 			return
 		}
 	}))
 	defer cst.close()
-	defer close(testDone) // before cst.close, to unblock /slow handler
 
-	// 200ms should be long enough to get a normal request (the /
-	// handler), but not so long that it makes the test slow.
-	const timeout = 200 * time.Millisecond
-	cst.c.Timeout = timeout
-
-	res, err := cst.c.Get(cst.ts.URL)
-	if err != nil {
-		if strings.Contains(err.Error(), "Client.Timeout") {
-			t.Skipf("host too slow to get fast resource in %v", timeout)
+	// Try to trigger a timeout after reading part of the response body.
+	// The initial timeout is emprically usually long enough on a decently fast
+	// machine, but if we undershoot we'll retry with exponentially longer
+	// timeouts until the test either passes or times out completely.
+	// This keeps the test reasonably fast in the typical case but allows it to
+	// also eventually succeed on arbitrarily slow machines.
+	timeout := 10 * time.Millisecond
+	nextNonce := 0
+	for ; ; timeout *= 2 {
+		if timeout <= 0 {
+			// The only way we can feasibly hit this while the test is running is if
+			// the request fails without actually waiting for the timeout to occur.
+			t.Fatalf("timeout overflow")
+		}
+		if deadline, ok := t.Deadline(); ok && !time.Now().Add(timeout).Before(deadline) {
+			t.Fatalf("failed to produce expected timeout before test deadline")
+		}
+		t.Logf("attempting test with timeout %v", timeout)
+		cst.c.Timeout = timeout
+
+		mu.Lock()
+		nonce = fmt.Sprint(nextNonce)
+		nextNonce++
+		sawSlowNonce = false
+		mu.Unlock()
+		res, err := cst.c.Get(cst.ts.URL + "/?nonce=" + nonce)
+		if err != nil {
+			if strings.Contains(err.Error(), "Client.Timeout") {
+				// Timed out before handler could respond.
+				t.Logf("timeout before response received")
+				continue
+			}
+			t.Fatal(err)
 		}
-		t.Fatal(err)
-	}
 
-	select {
-	case <-sawRoot:
-		// good.
-	default:
-		t.Fatal("handler never got / request")
-	}
-
-	select {
-	case <-sawSlow:
-		// good.
-	default:
-		t.Fatal("handler never got /slow request")
-	}
+		mu.Lock()
+		ok := sawSlowNonce
+		mu.Unlock()
+		if !ok {
+			t.Fatal("handler never got /slow request, but client returned response")
+		}
 
-	errc := make(chan error, 1)
-	go func() {
-		_, err := io.ReadAll(res.Body)
-		errc <- err
+		_, err = io.ReadAll(res.Body)
 		res.Body.Close()
-	}()
 
-	const failTime = 5 * time.Second
-	select {
-	case err := <-errc:
 		if err == nil {
 			t.Fatal("expected error from ReadAll")
 		}
@@ -1275,8 +1291,8 @@ func testClientTimeout(t *testing.T, h2 bool) {
 		if got := ne.Error(); !strings.Contains(got, "(Client.Timeout") {
 			t.Errorf("error string = %q; missing timeout substring", got)
 		}
-	case <-time.After(failTime):
-		t.Errorf("timeout after %v waiting for timeout of %v", failTime, timeout)
+
+		break
 	}
 }