net/http: prevent Transport from spamming stderr on server 408 reply

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 #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>

diff --git a/src/net/http/export_test.go b/src/net/http/export_test.go
index c33b88860a8800d832009f57d80e9563d6cb8f26..f0dfa8cd336c7a4efdf745bc625f984a4db9b3ff 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 5a1ebaac4c093cadac170af894e4e7b41cfcaf74..a3f674ca5c46a911f63e4d06fa5aa486b72f659a 100644 (file)
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -1911,7 +1911,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.
@@ -1921,6 +1926,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 21d26a24b258c5918f506558d34f9093bb99475b..2b58e1daecb844691bcef42185118ee8bbf3e5a2 100644 (file)
--- a/src/net/http/transport_test.go
+++ b/src/net/http/transport_test.go
@@ -5374,3 +5374,77 @@ func TestTransportClone(t *testing.T) {
                t.Errorf("Transport.TLSNextProto unexpected non-nil")
        }
 }
+
+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(log.Writer())
+
+       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))
+}