Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
winworm opened this issue Jan 10, 2018 · 7 comments
Closed
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@winworm
Copy link

winworm commented Jan 10, 2018

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

@bradfitz bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 10, 2018
@bradfitz bradfitz added this to the Go1.11 milestone Jan 10, 2018
@bradfitz bradfitz changed the title The original HTTP request,when timeout ,can't close the connection net/http: verify Transport discards HTTP/1.x connections upon request timeout Jan 10, 2018
@meirf
Copy link
Contributor

meirf commented May 5, 2018

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
Copy link
Author

winworm commented May 18, 2018

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
Copy link

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

@bradfitz
Copy link
Contributor

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.

gopherbot pushed a commit that referenced this issue Jul 12, 2018
For #23399

Change-Id: I9bc7c21fda6bfa89af2e7656e5c85aa9edd4f29e
Reviewed-on: https://go-review.googlesource.com/123435
Reviewed-by: Ian Lance Taylor <iant@golang.org>
@erifan
Copy link

erifan commented Jul 18, 2018

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
Copy link
Contributor

meirf commented Jul 18, 2018

@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.

gopherbot pushed a commit that referenced this issue Jul 19, 2018
It was flaky on slower machines.

Per report at #23399 (comment)

Change-Id: I7cab02821f78b5ce02ea51089d7eb51723f9705f
Reviewed-on: https://go-review.googlesource.com/124835
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
@erifan
Copy link

erifan commented Jul 19, 2018

@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.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

5 participants