net/http: verify Transport discards HTTP/1.x connections upon request timeout

[winworm]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.9.2 linux/amd64

Does this issue reproduce with the latest release?

no

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/git/go"
GORACE=""
GOROOT="installed/go"
GOTOOLDIR="/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build331671955=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

use client = &http.Client{Transport: transport, Timeout: 60} to invoke a http request
when timeout of this request has err info "Client.Timeout exceeded while awaiting headers" ,
it seems not close the connection after timeout.

If possible, provide a recipe for reproducing the error.
A complete runnable program is good.
A link on play.golang.org is best.

client = &http.Client{Transport: transport, Timeout: 60}
resp, err := client.Do(req)
if nil != err {
logger.Errorf("traceId={%s},clientDoError={%s}", speech.TraceId, err.Error())
return respText
}
defer resp.Body.Close()

What did you expect to see?

when timeout occur ,should close the connection, not cache the timeout connection

What did you see instead?

the connection is not closed when timeout

[meirf]

I was able to reproduce that if a Client request establishes a connection to a host, but the request times out, the connection is cached.

However, IMO I don't see why this behavior is undesirable or unexpected. If a connection is successfully established, I don't think it should be discarded just because a request happens to take a long time. If there's nothing wrong with the connection, why not keep it. If the first request that uses a connection times out, I agree there's a high likelihood that future requests will also timeout, but at least we would have the efficiency of the cached connection.

The code included by the OP is incomplete (@winworm , what is transport?). Below is code that is probably close to what was intended. Use -transpdialtimeout=30s -clienttimeout=1µs to simulate DefaultTransport and very short Client timeout.

var transpDialTimeout = flag.Duration("transpdialtimeout", 0,
	"transport dial timeout")
var clientTimeout = flag.Duration("clienttimeout", 0,
	"client timeout")

func main() {
	flag.Parse()
	// same as http.DefaultTransport except transpDialTimeout is configurable
	transp := &http.Transport{
		Proxy: http.ProxyFromEnvironment,
		DialContext: (&net.Dialer{
			Timeout:   *transpDialTimeout,
			KeepAlive: 30 * time.Second,
			DualStack: true,
		}).DialContext,
		MaxIdleConns:          100,
		IdleConnTimeout:       90 * time.Second,
		TLSHandshakeTimeout:   10 * time.Second,
		ExpectContinueTimeout: 1 * time.Second,
	}
	client := &http.Client{
		Transport: transp,
		Timeout:   *clientTimeout,
	}

	req, err := http.NewRequest(http.MethodGet, "http://example.com", nil)
	if err != nil {
		log.Fatal(err)
	}
	_, err = client.Do(req)
	fmt.Println(err)
        // include reading resp body and closing if err is not nil

	fmt.Println("Sleeping so you have time to look around at e.g. lsof -p PID ...")
	time.Sleep(2 * time.Minute)
}

[winworm]

thanks to meirf ，Mainly because in some special cases, the client set the timeout specified, the client did not send the specified protocol data to the server (such as bandwidth limitations caused by the server did not receive), the server will continue to maintain the connection until the server set the timeout time (this time is greater than the client timeout setting). So we want the client to be able to control whether or not to close the connection over time and not into the pool.

[gopherbot]

Change https://golang.org/cl/123435 mentions this issue: net/http: add tests to validate that Client.Timeout closes connections

[bradfitz]

I investigated this and wrote some tests (https://go-review.googlesource.com/c/go/+/123435) but was not able to reproduce. It seems to be doing the correct thing and closing the connection on timeout.

I'm going to close this.

Also, unrelated: the code &http.Client{Transport: transport, Timeout: 60} means 60 nanoseconds, not 60 seconds, which you probably discovered while reporting this bug I imagine.

[erifan]

Change https://golang.org/cl/123435 seems to broke all.bash occasionally both on amd64 and arm64.
Logs on amd64:

23:07:24 2018/07/17 22:07:21 http: panic serving 127.0.0.1:55952: Fail in goroutine after TestClientTimeoutKillsConn_AfterHeaders has completed
23:07:24 goroutine 3032 [running]:
23:07:24 net/http.(*conn).serve.func1(0xc0004180a0)
23:07:24 /home/root/ci-scripts/golang/src/net/http/server.go:1754 +0xd0
23:07:24 panic(0x859240, 0xc000eb4030)
23:07:24 /home/root/ci-scripts/golang/src/runtime/panic.go:513 +0x1b9
23:07:24 testing.(*common).Fail(0xc00062ef00)
23:07:24 /home/root/ci-scripts/golang/src/testing/testing.go:546 +0x135
23:07:24 testing.(*common).Errorf(0xc00062ef00, 0x90bcdf, 0x1e, 0xc0002e0cf0, 0x2, 0x2)
23:07:24 /home/root/ci-scripts/golang/src/testing/testing.go:622 +0x83
23:07:24 net/http_test.TestClientTimeoutKillsConn_AfterHeaders.func1(0x9929c0, 0xc0009f02a0, 0xc000293500)
23:07:24 /home/root/ci-scripts/golang/src/net/http/transport_test.go:4780 +0x338
23:07:24 net/http.HandlerFunc.ServeHTTP(0xc00031a060, 0x9929c0, 0xc0009f02a0, 0xc000293500)
23:07:24 /home/root/ci-scripts/golang/src/net/http/server.go:1972 +0x44
23:07:24 net/http.serverHandler.ServeHTTP(0xc0005825b0, 0x9929c0, 0xc0009f02a0, 0xc000293500)
23:07:24 /home/root/ci-scripts/golang/src/net/http/server.go:2740 +0xab
23:07:24 net/http.(*conn).serve(0xc0004180a0, 0x993200, 0xc0006b4300)
23:07:24 /home/root/ci-scripts/golang/src/net/http/server.go:1855 +0x646
23:07:24 created by net/http.(*Server).Serve
23:07:24 /home/root/ci-scripts/golang/src/net/http/server.go:2848 +0x2f5
23:07:24 FAIL
23:07:24 FAIL net/http 3.217s

Logs on arm64:

13:10:14 --- FAIL: TestClientTimeoutKillsConn_AfterHeaders (0.06s)
13:10:14 transport_test.go:4793: Get error: Get http://127.0.0.1:35605: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
13:10:14 FAIL
13:10:14 FAIL net/http 3.331s

[meirf]

@erifan if you haven't already, best to create a new issue instead of continuing the conversation here since the problems are different. This issue is about validating that Client.Timeout closes connections. The new separate issue would be about those validation tests being flaky.

[erifan]

@meirf OK, I'll do it in the future. I did not study this issue, but found that the change was cited here, so I thought it was the same question. Excuse me.