x/net/http2: Transport leaks goroutines (newClientConn)

[jeanbza]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/deklerk/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/deklerk/workspace/go"
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
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"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lk/zs4m7sv12mq2vzk_wfn2tfvm00h16k/T/go-build884605322=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Using github.com/fortytw2/leaktest

func TestJean(t *testing.T) {
	defer leaktest.Check(t)()
	req, err := http.NewRequest("GET", "https://google.com", nil)
	if err != nil {
		panic(err)
	}
	c := http.Client{}
	resp, err := c.Do(req)
	if err != nil {
		panic(err)
	}
	fmt.Println(resp.StatusCode)
}

go test -v -run TestJean

What did you expect to see?

PASS

What did you see instead?

$ go test -v -run TestJean
=== RUN   TestJean
200
--- FAIL: TestJean (5.31s)
	leaktest.go:129: leaktest: timed out checking goroutines
	leaktest.go:147: leaktest: leaked goroutine: goroutine 59 [IO wait]:
		internal/poll.runtime_pollWait(0x1e44d60, 0x72, 0xc420063858)
			/usr/local/go/src/runtime/netpoll.go:173 +0x57
		internal/poll.(*pollDesc).wait(0xc420406118, 0x72, 0xffffffffffffff00, 0x16bd680, 0x194f608)
			/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
		internal/poll.(*pollDesc).waitRead(0xc420406118, 0xc4200c1c00, 0x400, 0x400)
			/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
		internal/poll.(*FD).Read(0xc420406100, 0xc4200c1c00, 0x400, 0x400, 0x0, 0x0, 0x0)
			/usr/local/go/src/internal/poll/fd_unix.go:157 +0x1dc
		net.(*netFD).Read(0xc420406100, 0xc4200c1c00, 0x400, 0x400, 0x1035769, 0xc4201d3200, 0x200000003)
			/usr/local/go/src/net/fd_unix.go:202 +0x4f
		net.(*conn).Read(0xc4201da008, 0xc4200c1c00, 0x400, 0x400, 0x0, 0x0, 0x0)
			/usr/local/go/src/net/net.go:176 +0x6a
		crypto/tls.(*block).readFromUntil(0xc4201d8180, 0x1ec0000, 0xc4201da008, 0x5, 0xc4201da008, 0xc420063a10)
			/usr/local/go/src/crypto/tls/conn.go:493 +0x96
		crypto/tls.(*Conn).readRecord(0xc4201e0700, 0x1674817, 0xc4201e0820, 0xc4201d3200)
			/usr/local/go/src/crypto/tls/conn.go:595 +0xe0
		crypto/tls.(*Conn).Read(0xc4201e0700, 0xc420441000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/go/src/crypto/tls/conn.go:1156 +0x100
		bufio.(*Reader).Read(0xc4201903c0, 0xc420432ab8, 0x9, 0x9, 0xc4201e0a30, 0x1221f90, 0xc4201e0a30)
			/usr/local/go/src/bufio/bufio.go:216 +0x238
		io.ReadAtLeast(0x16bb4e0, 0xc4201903c0, 0xc420432ab8, 0x9, 0x9, 0x9, 0x128f261, 0xc4201e0700, 0xc420440000)
			/usr/local/go/src/io/io.go:309 +0x86
		io.ReadFull(0x16bb4e0, 0xc4201903c0, 0xc420432ab8, 0x9, 0x9, 0x12d5aa4, 0x1e4d1d8, 0xc4201e0700)
			/usr/local/go/src/io/io.go:327 +0x58
		net/http.http2readFrameHeader(0xc420432ab8, 0x9, 0x9, 0x16bb4e0, 0xc4201903c0, 0x0, 0xc400000000, 0x102bda4, 0x16748f0)
			/usr/local/go/src/net/http/h2_bundle.go:1517 +0x7b
		net/http.(*http2Framer).ReadFrame(0xc420432a80, 0xc4203cc780, 0x0, 0x0, 0x0)
			/usr/local/go/src/net/http/h2_bundle.go:1775 +0xa4
		net/http.(*http2clientConnReadLoop).run(0xc420063fb8, 0x1674218, 0xc42047e7b8)
			/usr/local/go/src/net/http/h2_bundle.go:8028 +0x90
		net/http.(*http2ClientConn).readLoop(0xc42027b340)
			/usr/local/go/src/net/http/h2_bundle.go:7956 +0x68
		created by net/http.(*http2Transport).newClientConn
			/usr/local/go/src/net/http/h2_bundle.go:7143 +0x65c
	leaktest.go:147: leaktest: leaked goroutine: goroutine 85 [IO wait]:
		internal/poll.runtime_pollWait(0x1e44c90, 0x72, 0xc420064858)
			/usr/local/go/src/runtime/netpoll.go:173 +0x57
		internal/poll.(*pollDesc).wait(0xc42018e398, 0x72, 0xffffffffffffff00, 0x16bd680, 0x194f608)
			/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
		internal/poll.(*pollDesc).waitRead(0xc42018e398, 0xc4201a7000, 0x1000, 0x1000)
			/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
		internal/poll.(*FD).Read(0xc42018e380, 0xc4201a7000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/go/src/internal/poll/fd_unix.go:157 +0x1dc
		net.(*netFD).Read(0xc42018e380, 0xc4201a7000, 0x1000, 0x1000, 0x102bb3b, 0xc420087080, 0x200000003)
			/usr/local/go/src/net/fd_unix.go:202 +0x4f
		net.(*conn).Read(0xc42020c000, 0xc4201a7000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/go/src/net/net.go:176 +0x6a
		crypto/tls.(*block).readFromUntil(0xc420180420, 0x1ec0000, 0xc42020c000, 0x5, 0xc42020c000, 0xc420064a70)
			/usr/local/go/src/crypto/tls/conn.go:493 +0x96
		crypto/tls.(*Conn).readRecord(0xc4201b6700, 0x1674817, 0xc4201b6820, 0xc420087080)
			/usr/local/go/src/crypto/tls/conn.go:595 +0xe0
		crypto/tls.(*Conn).Read(0xc4201b6700, 0xc4201a6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
			/usr/local/go/src/crypto/tls/conn.go:1156 +0x100
		bufio.(*Reader).Read(0xc420090720, 0xc420304ab8, 0x9, 0x9, 0xc4201b6a30, 0x1221f90, 0xc4201b6a30)
			/usr/local/go/src/bufio/bufio.go:216 +0x238
		io.ReadAtLeast(0x16bb4e0, 0xc420090720, 0xc420304ab8, 0x9, 0x9, 0x9, 0x128f2b8, 0xc4201b6700, 0xc420307000)
			/usr/local/go/src/io/io.go:309 +0x86
		io.ReadFull(0x16bb4e0, 0xc420090720, 0xc420304ab8, 0x9, 0x9, 0x12d5aa4, 0x1e4d1d8, 0xc4201b6700)
			/usr/local/go/src/io/io.go:327 +0x58
		net/http.http2readFrameHeader(0xc420304ab8, 0x9, 0x9, 0x16bb4e0, 0xc420090720, 0x0, 0xc400000000, 0x102bda4, 0x16748f0)
			/usr/local/go/src/net/http/h2_bundle.go:1517 +0x7b
		net/http.(*http2Framer).ReadFrame(0xc420304a80, 0xc42038fe20, 0x0, 0x0, 0x0)
			/usr/local/go/src/net/http/h2_bundle.go:1775 +0xa4
		net/http.(*http2clientConnReadLoop).run(0xc420064fb8, 0x1674218, 0xc42047e7b8)
			/usr/local/go/src/net/http/h2_bundle.go:8028 +0x90
		net/http.(*http2ClientConn).readLoop(0xc42038a540)
			/usr/local/go/src/net/http/h2_bundle.go:7956 +0x68
		created by net/http.(*http2Transport).newClientConn
			/usr/local/go/src/net/http/h2_bundle.go:7143 +0x65c
FAIL

[agnivade]

Happens on 1.9 too.

Can you post a self-contained reproducer without the dependency on leaktest ?

/cc @bradfitz

[jeanbza]

Can you post a self-contained reproducer without the dependency on leaktest ?

As in, write a leaktest myself?

[agnivade]

You can even copy the relevant code if that makes it easier. But yes, a self-contained repro without any external dependency is preferred. We can even turn this into a main function without a test setup.

[jeanbza]

This should do it https://gist.github.com/jadekler/ce72bbc03abafdf67930c5d018dae4df

[meirf]

From the doc:

The Client's Transport typically has internal state (cached TCP connections)...

In this case it's a connection that is being used for h2 messages. TCP connections used for h2 are long lived. When http requests/responses are going back and forth, there needs to be some concurrent code (http2ClientConn.readLoop) which reads frames from the wire and dispatches to the various requestors. But even when there are no http requests/responses on the wire, there are various h2 frames which the server might send the client.

@jadekler it looks like you have some h2 experience. Maybe you can help me understand what the proper behavior should be/why my logic is incorrect.

[bwplotka]

Thanks, @jadekler for reporting this issue and @meirf thanks for clarifying the problem. The need for some concurrent code is clear here. Just it is kind of not fair nor clean to keep them running around if user explicitly wants to close his http.Client. I double checked the code, and it seems that Client's http.Transport (if this transport is set) has access to ConnPool which needs to be "closed" (all it's TCP connections needs be closed). It sounds like we need explicit http.Client Close method here, so maybe adding Close method to http.Transport is something that would help here? (Or even adding RoundTripperCloser or something like this, but not sure if that's smart).

I guess this is big change, but we cannot close background go routines implicitly.

[bradfitz]

I don't see the bug here. As @meirf said, this is working as intended. The "leaked" goroutines are intentionally running because they're the cached connection to make future HTTP requests to the same host faster. This happens for both HTTP/1 and HTTP/2.

Use https://golang.org/pkg/net/http/#Transport.CloseIdleConnections to close idle connections if you want to shut them down.

[jeanbza]

@bradfitz That makes sense, but it's not clear to me how to get at using that method. In github.com/GoogleCloudPlatform/google-cloud-go our clients have many-layered transports; oauth2.Transport -> ochttp.Transport -> http.userAgentTransport -> ... -> http.Transport.

Is there some better way than the following to get at that method?

c.hc.Transport.(*oauth2.Transport).Base.(*ochttp.Transport).Base.(*http.Transport).CloseIdleConnections()

If that is the way to get to it; what if one transport in the stack (such as http.userAgentTransport is unexported? Are we out of luck?

[bradfitz]

The cloud & oauth2 libraries all support passing down a client/transport if that matters. (see https://godoc.org/golang.org/x/oauth2#HTTPClient)

Then you can just retain your old Transport (to call close on it) and not use the default (unexported) one in their code.

[bwplotka]

Thanks! defering CloseIdleConnections (after defering leaktest) seems to work perfectly for this use case.

BTW is there any mention about this behavior (leaving some go routines for a while) in the some net/http godoc or something? Can we add some note at least? It sounds like the correct flow is to always do defer http.DefaultTransport.(*http.Transport).CloseIdleConnections() if you use DefaultTransport before every unit test that use http/http2 requests to have proper clean state before each unit test, right?

[bradfitz]

BTW is there any mention about this behavior (leaving some go routines for a while) in the some net/http godoc or something?

There is:

https://golang.org/pkg/net/http/#Transport

By default, Transport caches connections for future re-use. This may leave many open connections when accessing many hosts. This behavior can be managed using Transport's CloseIdleConnections method and the MaxIdleConnsPerHost and DisableKeepAlives fields.

[bwplotka]

perfect, thanks.