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

Jump to bottom

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

Closed
jeanbza opened this issue Jun 6, 2018 · 12 comments
Closed

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

jeanbza opened this issue Jun 6, 2018 · 12 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.12

Comments

@jeanbza
Copy link
Member

jeanbza commented Jun 6, 2018

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
@jeanbza jeanbza mentioned this issue Jun 6, 2018
Closed
@agnivade
Copy link
Contributor

agnivade commented Jun 6, 2018

Happens on 1.9 too.

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

/cc @bradfitz

@agnivade agnivade added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jun 6, 2018
@agnivade agnivade added this to the Go1.12 milestone Jun 6, 2018
@jeanbza
Copy link
Member Author

jeanbza commented Jun 6, 2018

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

As in, write a leaktest myself?

@agnivade
Copy link
Contributor

agnivade commented Jun 6, 2018

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

jeanbza commented Jun 6, 2018 •
edited

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

@meirf
Copy link
Contributor

meirf commented Jun 7, 2018 •
edited

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

bwplotka commented Jun 7, 2018

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

bradfitz commented Jun 7, 2018

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.

@bradfitz bradfitz closed this as completed Jun 7, 2018
@jeanbza
Copy link
Member Author

jeanbza commented Jun 7, 2018

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

bradfitz commented Jun 7, 2018

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

bwplotka commented Jun 8, 2018 •
edited

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

bradfitz commented Jun 8, 2018

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

bwplotka commented Jun 8, 2018

perfect, thanks.

@golang golang locked and limited conversation to collaborators Jun 8, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.12
Development

No branches or pull requests
6 participants
@bradfitz @agnivade @meirf @jeanbza @bwplotka @gopherbot