[release-branch.go1.12] net/http: prevent Transport from spamming stderr on server...

HTTP 408 responses now exist and are seen in the wild (e.g. from
Google's GFE), so make Go's HTTP client not spam about them when seen.
They're normal (now).

Fixes #32367
Updates #32310

Change-Id: I558eb4654960c74cf20db1902ccaae13d03310f6
Reviewed-on: https://go-review.googlesource.com/c/go/+/179457
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
(cherry picked from commit ba66d89d7882892f762e7980562287d2c79ad87e)
Reviewed-on: https://go-review.googlesource.com/c/go/+/181239
Run-TryBot: Dmitri Shuralyov <dmitshur@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

diff --git a/src/net/http/export_test.go b/src/net/http/export_test.go
index b6965c239e95ecbdcf000d0f53dd7744a55546fa..d605b637d88096e550b932ee26ccd93e3812e99a 100644 (file)
--- a/src/net/http/export_test.go
+++ b/src/net/http/export_test.go
@@ -33,6 +33,7 @@ var (
        ExportHttp2ConfigureServer        = http2ConfigureServer
        Export_shouldCopyHeaderOnRedirect = shouldCopyHeaderOnRedirect
        Export_writeStatusLine            = writeStatusLine
+       Export_is408Message               = is408Message
 )
 
 const MaxWriteWaitBeforeConnReuse = maxWriteWaitBeforeConnReuse

diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index a8c5efe6aaff2918498b0aa2f43d9c5adb91bd64..07920cfde31bd1e34461101628bfffa5e5049876 100644 (file)
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -1826,7 +1826,12 @@ func (pc *persistConn) readLoopPeekFailLocked(peekErr error) {
        }
        if n := pc.br.Buffered(); n > 0 {
                buf, _ := pc.br.Peek(n)
-               log.Printf("Unsolicited response received on idle HTTP channel starting with %q; err=%v", buf, peekErr)
+               if is408Message(buf) {
+                       pc.closeLocked(errServerClosedIdle)
+                       return
+               } else {
+                       log.Printf("Unsolicited response received on idle HTTP channel starting with %q; err=%v", buf, peekErr)
+               }
        }
        if peekErr == io.EOF {
                // common case.
@@ -1836,6 +1841,19 @@ func (pc *persistConn) readLoopPeekFailLocked(peekErr error) {
        }
 }
 
+// is408Message reports whether buf has the prefix of an
+// HTTP 408 Request Timeout response.
+// See golang.org/issue/32310.
+func is408Message(buf []byte) bool {
+       if len(buf) < len("HTTP/1.x 408") {
+               return false
+       }
+       if string(buf[:7]) != "HTTP/1." {
+               return false
+       }
+       return string(buf[8:12]) == " 408"
+}
+
 // readResponse reads an HTTP response (or two, in the case of "Expect:
 // 100-continue") from the server. It returns the final non-100 one.
 // trace is optional.

diff --git a/src/net/http/transport_test.go b/src/net/http/transport_test.go
index 6e075847ddeeadd2802c46b29e182637be4ed4df..f66e72a00fb942eb67e64e48b11af07827a088d8 100644 (file)
--- a/src/net/http/transport_test.go
+++ b/src/net/http/transport_test.go
@@ -5059,3 +5059,77 @@ func TestTransportRequestReplayable(t *testing.T) {
                })
        }
 }
+
+func TestIs408(t *testing.T) {
+       tests := []struct {
+               in   string
+               want bool
+       }{
+               {"HTTP/1.0 408", true},
+               {"HTTP/1.1 408", true},
+               {"HTTP/1.8 408", true},
+               {"HTTP/2.0 408", false}, // maybe h2c would do this? but false for now.
+               {"HTTP/1.1 408 ", true},
+               {"HTTP/1.1 40", false},
+               {"http/1.0 408", false},
+               {"HTTP/1-1 408", false},
+       }
+       for _, tt := range tests {
+               if got := Export_is408Message([]byte(tt.in)); got != tt.want {
+                       t.Errorf("is408Message(%q) = %v; want %v", tt.in, got, tt.want)
+               }
+       }
+}
+
+func TestTransportIgnores408(t *testing.T) {
+       // Not parallel. Relies on mutating the log package's global Output.
+       defer log.SetOutput(os.Stderr)
+
+       var logout bytes.Buffer
+       log.SetOutput(&logout)
+
+       defer afterTest(t)
+       const target = "backend:443"
+
+       cst := newClientServerTest(t, h1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
+               nc, _, err := w.(Hijacker).Hijack()
+               if err != nil {
+                       t.Error(err)
+                       return
+               }
+               defer nc.Close()
+               nc.Write([]byte("HTTP/1.1 200 OK\r\nContent-Length: 2\r\n\r\nok"))
+               nc.Write([]byte("HTTP/1.1 408 bye\r\n")) // changing 408 to 409 makes test fail
+       }))
+       defer cst.close()
+       req, err := NewRequest("GET", cst.ts.URL, nil)
+       if err != nil {
+               t.Fatal(err)
+       }
+       res, err := cst.c.Do(req)
+       if err != nil {
+               t.Fatal(err)
+       }
+       slurp, err := ioutil.ReadAll(res.Body)
+       if err != nil {
+               t.Fatal(err)
+       }
+       if err != nil {
+               t.Fatal(err)
+       }
+       if string(slurp) != "ok" {
+               t.Fatalf("got %q; want ok", slurp)
+       }
+
+       t0 := time.Now()
+       for i := 0; i < 50; i++ {
+               time.Sleep(time.Duration(i) * 5 * time.Millisecond)
+               if cst.tr.IdleConnKeyCountForTesting() == 0 {
+                       if got := logout.String(); got != "" {
+                               t.Fatalf("expected no log output; got: %s", got)
+                       }
+                       return
+               }
+       }
+       t.Fatalf("timeout after %v waiting for Transport connections to die off", time.Since(t0))
+}