net/http: Transport doesn't discard connections which received a 408 Request Timeout

[ktock]

What version of Go are you using (go version)?

$ go version
go version go1.14.2 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build338312077=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I'm reading net/http for implementing HTTP client in Go. I want to use connections pool functionality of it but not sure how to deal with the stale connections.

*http.Transport says it retries the request if a connection got closed by server while it was trying to read the response.

go/src/net/http/transport.go

Lines 640 to 645 in a88c26e

	if err == errServerClosedIdle {
	// The server replied with io.EOF while we were trying to
	// read the response. Probably an unfortunately keep-alive
	// timeout, just as the client was writing a request.
	return true
	}

Since #32310, the connection is discarded also when 408 Request Timeout is sent on it.

go/src/net/http/transport.go

Lines 2127 to 2135 in a88c26e

	func (pc *persistConn) readLoopPeekFailLocked(peekErr error) {
	if pc.closed != nil {
	return
	}
	if n := pc.br.Buffered(); n > 0 {
	buf, _ := pc.br.Peek(n)
	if is408Message(buf) {
	pc.closeLocked(errServerClosedIdle)
	return

But if a connection receives 408 as a response to the request, no retry is held and that connection doesn't get discarded. So the client of *http.Transport sees 408 response repeatedly until that connection actually gets closed from the server.

Two open questions:

• Is it the client(of *http.Transport)'s responsibility to retry the request when it sees 408?
• And why *http.Transport doesn't discard connections which got 408?

You can reproduce this situation with the server which responses 408 for requests but doesn't close the connection immediately:

package main

import (
	"context"
	"fmt"
	"io"
	"io/ioutil"
	"net/http"
	"net/http/httptest"
	"net/http/httptrace"
	"runtime"
	"time"
)

func main() {
	fmt.Println(runtime.Version())

	server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
		http.Error(rw, "", http.StatusRequestTimeout)
	}))
	defer server.Close()

	req, err := http.NewRequestWithContext(
		httptrace.WithClientTrace(context.Background(), &httptrace.ClientTrace{
			GotConn: func(info httptrace.GotConnInfo) {
				fmt.Printf("WasIdle: %v\n", info.WasIdle)
			},
		}),
		"GET", server.URL, nil,
	)
	if err != nil {
		panic(err)
	}

	for i := 0; i < 3; i++ {
		fmt.Printf("===== %d =====\n", i)
		res, err := http.DefaultTransport.RoundTrip(req)
		if err != nil {
			panic(err)
		}
		fmt.Println(res)
		io.Copy(ioutil.Discard, res.Body)
		res.Body.Close()
		time.Sleep(time.Second)
	}
}

Then the client always sees 408 through the cached connection.

go1.14.2
===== 0 =====
WasIdle: false
&{408 Request Timeout 408 HTTP/1.1 1 1 map[Content-Length:[1] Content-Type:[text/plain; charset=utf-8] Date:[Thu, 14 May 2020 02:00:53 GMT] X-Content-Type-Options:[nosniff]] 0xc000190080 1 [] false false map[] 0xc000142000 <nil>}
===== 1 =====
WasIdle: true
&{408 Request Timeout 408 HTTP/1.1 1 1 map[Content-Length:[1] Content-Type:[text/plain; charset=utf-8] Date:[Thu, 14 May 2020 02:00:54 GMT] X-Content-Type-Options:[nosniff]] 0xc000092240 1 [] false false map[] 0xc000142000 <nil>}
===== 2 =====
WasIdle: true
&{408 Request Timeout 408 HTTP/1.1 1 1 map[Content-Length:[1] Content-Type:[text/plain; charset=utf-8] Date:[Thu, 14 May 2020 02:00:55 GMT] X-Content-Type-Options:[nosniff]] 0xc00021e080 1 [] false false map[] 0xc000142000 <nil>}

What did you expect to see?

When *http.Transport get 408 as a response, it should discard the connection and retry with another.

What did you see instead?

When *http.Transport get 408 as a response, it doesn't discard the connection nor retry.

[cagedmantis]

/cc @bradfitz @bcmills

[bcmills]

Per https://tools.ietf.org/html/rfc7231#section-6.5.7:

A server SHOULD send the "close" connection option
(Section 6.1 of [RFC7230]) in the response, since 408 implies that
the server has decided to close the connection rather than continue
waiting.

Does this server, in fact, close the connection?

Per https://pkg.go.dev/net/http?tab=doc#Error:

Error replies to the request with the specified error message and HTTP code. It does not otherwise end the request; the caller should ensure no further writes are done to w.

That suggests to me that it does not, but I don't actually know offhand. (Perhaps @bradfitz has more insight?)

---

Also per https://tools.ietf.org/html/rfc7231#section-6.5.7:

If the client has an outstanding request in transit, the
client MAY repeat that request on a new connection.

The use of the word “MAY” indicates that *http.Transport complies with the RFC even if it does not retry. So if there is a bug here, I suspect that it is on the server side.