Skip to content

Commit ba66d89

Browse files
committed
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 <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Dmitri Shuralyov <[email protected]>
1 parent 103b5b6 commit ba66d89

File tree

3 files changed

+94
-1
lines changed

3 files changed

+94
-1
lines changed

src/net/http/export_test.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ var (
3333
ExportHttp2ConfigureServer = http2ConfigureServer
3434
Export_shouldCopyHeaderOnRedirect = shouldCopyHeaderOnRedirect
3535
Export_writeStatusLine = writeStatusLine
36+
Export_is408Message = is408Message
3637
)
3738

3839
const MaxWriteWaitBeforeConnReuse = maxWriteWaitBeforeConnReuse

src/net/http/transport.go

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1911,7 +1911,12 @@ func (pc *persistConn) readLoopPeekFailLocked(peekErr error) {
19111911
}
19121912
if n := pc.br.Buffered(); n > 0 {
19131913
buf, _ := pc.br.Peek(n)
1914-
log.Printf("Unsolicited response received on idle HTTP channel starting with %q; err=%v", buf, peekErr)
1914+
if is408Message(buf) {
1915+
pc.closeLocked(errServerClosedIdle)
1916+
return
1917+
} else {
1918+
log.Printf("Unsolicited response received on idle HTTP channel starting with %q; err=%v", buf, peekErr)
1919+
}
19151920
}
19161921
if peekErr == io.EOF {
19171922
// common case.
@@ -1921,6 +1926,19 @@ func (pc *persistConn) readLoopPeekFailLocked(peekErr error) {
19211926
}
19221927
}
19231928

1929+
// is408Message reports whether buf has the prefix of an
1930+
// HTTP 408 Request Timeout response.
1931+
// See golang.org/issue/32310.
1932+
func is408Message(buf []byte) bool {
1933+
if len(buf) < len("HTTP/1.x 408") {
1934+
return false
1935+
}
1936+
if string(buf[:7]) != "HTTP/1." {
1937+
return false
1938+
}
1939+
return string(buf[8:12]) == " 408"
1940+
}
1941+
19241942
// readResponse reads an HTTP response (or two, in the case of "Expect:
19251943
// 100-continue") from the server. It returns the final non-100 one.
19261944
// trace is optional.

src/net/http/transport_test.go

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5374,3 +5374,77 @@ func TestTransportClone(t *testing.T) {
53745374
t.Errorf("Transport.TLSNextProto unexpected non-nil")
53755375
}
53765376
}
5377+
5378+
func TestIs408(t *testing.T) {
5379+
tests := []struct {
5380+
in string
5381+
want bool
5382+
}{
5383+
{"HTTP/1.0 408", true},
5384+
{"HTTP/1.1 408", true},
5385+
{"HTTP/1.8 408", true},
5386+
{"HTTP/2.0 408", false}, // maybe h2c would do this? but false for now.
5387+
{"HTTP/1.1 408 ", true},
5388+
{"HTTP/1.1 40", false},
5389+
{"http/1.0 408", false},
5390+
{"HTTP/1-1 408", false},
5391+
}
5392+
for _, tt := range tests {
5393+
if got := Export_is408Message([]byte(tt.in)); got != tt.want {
5394+
t.Errorf("is408Message(%q) = %v; want %v", tt.in, got, tt.want)
5395+
}
5396+
}
5397+
}
5398+
5399+
func TestTransportIgnores408(t *testing.T) {
5400+
// Not parallel. Relies on mutating the log package's global Output.
5401+
defer log.SetOutput(log.Writer())
5402+
5403+
var logout bytes.Buffer
5404+
log.SetOutput(&logout)
5405+
5406+
defer afterTest(t)
5407+
const target = "backend:443"
5408+
5409+
cst := newClientServerTest(t, h1Mode, HandlerFunc(func(w ResponseWriter, r *Request) {
5410+
nc, _, err := w.(Hijacker).Hijack()
5411+
if err != nil {
5412+
t.Error(err)
5413+
return
5414+
}
5415+
defer nc.Close()
5416+
nc.Write([]byte("HTTP/1.1 200 OK\r\nContent-Length: 2\r\n\r\nok"))
5417+
nc.Write([]byte("HTTP/1.1 408 bye\r\n")) // changing 408 to 409 makes test fail
5418+
}))
5419+
defer cst.close()
5420+
req, err := NewRequest("GET", cst.ts.URL, nil)
5421+
if err != nil {
5422+
t.Fatal(err)
5423+
}
5424+
res, err := cst.c.Do(req)
5425+
if err != nil {
5426+
t.Fatal(err)
5427+
}
5428+
slurp, err := ioutil.ReadAll(res.Body)
5429+
if err != nil {
5430+
t.Fatal(err)
5431+
}
5432+
if err != nil {
5433+
t.Fatal(err)
5434+
}
5435+
if string(slurp) != "ok" {
5436+
t.Fatalf("got %q; want ok", slurp)
5437+
}
5438+
5439+
t0 := time.Now()
5440+
for i := 0; i < 50; i++ {
5441+
time.Sleep(time.Duration(i) * 5 * time.Millisecond)
5442+
if cst.tr.IdleConnKeyCountForTesting() == 0 {
5443+
if got := logout.String(); got != "" {
5444+
t.Fatalf("expected no log output; got: %s", got)
5445+
}
5446+
return
5447+
}
5448+
}
5449+
t.Fatalf("timeout after %v waiting for Transport connections to die off", time.Since(t0))
5450+
}

0 commit comments

Comments
 (0)