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.

Sign up for GitHub

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: client leaks connection after receiving GOAWAY frame #39752

Closed
zhangyoufu opened this issue Jun 22, 2020 · 8 comments
Closed

x/net/http2: client leaks connection after receiving GOAWAY frame #39752

zhangyoufu opened this issue Jun 22, 2020 · 8 comments
Assignees
@neild
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@zhangyoufu
Copy link
Contributor

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

$ go version
go version go1.14.4 linux/amd64

Does this issue reproduce with the latest release?

Yes

What did you do?

After receiving GOAWAY frame from server, the underlying connection is not reused nor closed. The following code shows that the connection is not closed after a single HTTP request and CloseIdleConnections().

package main

import (
	"crypto/tls"
	"log"
	"net"
	"net/http"
	"time"

	"golang.org/x/net/http2"
)

var client = http.Client{
	Transport: &http2.Transport{
		DialTLS: dialTLS,
	},
}

var tlsConn *tls.Conn

// dial a TLS.Conn and keep in global variable for reference later
func dialTLS(network, addr string, cfg *tls.Config) (net.Conn, error) {
	var err error
	tlsConn, err = tls.Dial(network, addr, cfg)
	return tlsConn, err
}

func main() {
	req, err := http.NewRequest("HEAD", "https://download.developer.apple.com/", nil)
	if err != nil {
		log.Fatal(err)
	}
	req.Header.Set("Cookie", "ADCDownloadAuth=A")
	rsp, err := client.Do(req)
	if err != nil {
		log.Fatal(err)
	}
	_ = rsp.Body.Close()
	log.Print("HTTP request/response done")

	time.Sleep(3 * time.Second)

	log.Print("before CloseIdleConnections()")
	client.CloseIdleConnections()
	log.Print("after CloseIdleConnections()")

	time.Sleep(3 * time.Second)

	log.Print("Close(): ", tlsConn.Close()) // should be "tls: use of closed connection"
}

What did you expect to see?

The TLS.Conn should have been closed when I call tlsConn.Close() in main.

What did you see instead?

The TLS.Conn seems to be leaked and is not closed. tlsConn.Close() returns nil.

http2debug log 
# GODEBUG=http2debug=2 go run .
2020/06/22 17:40:29 http2: Transport creating client conn 0xc000001680 to 17.253.27.202:443
2020/06/22 17:40:29 http2: Framer 0xc000338620: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/22 17:40:29 http2: Framer 0xc000338620: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/22 17:40:29 http2: Transport encoding header ":authority" = "download.developer.apple.com"
2020/06/22 17:40:29 http2: Transport encoding header ":method" = "HEAD"
2020/06/22 17:40:29 http2: Transport encoding header ":path" = "/"
2020/06/22 17:40:29 http2: Transport encoding header ":scheme" = "https"
2020/06/22 17:40:29 http2: Transport encoding header "cookie" = "ADCDownloadAuth=A"
2020/06/22 17:40:29 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/22 17:40:29 http2: Framer 0xc000338620: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=60
2020/06/22 17:40:29 http2: Framer 0xc000338620: read SETTINGS len=12, settings: MAX_CONCURRENT_STREAMS=100, MAX_HEADER_LIST_SIZE=131072
2020/06/22 17:40:29 http2: Transport received SETTINGS len=12, settings: MAX_CONCURRENT_STREAMS=100, MAX_HEADER_LIST_SIZE=131072
2020/06/22 17:40:29 http2: Framer 0xc000338620: wrote SETTINGS flags=ACK len=0
2020/06/22 17:40:29 http2: Framer 0xc000338620: read SETTINGS flags=ACK len=0
2020/06/22 17:40:29 http2: Transport received SETTINGS flags=ACK len=0
2020/06/22 17:40:29 http2: Framer 0xc000338620: read HEADERS flags=END_HEADERS stream=1 len=211
2020/06/22 17:40:29 http2: decoded hpack field header field ":status" = "403"
2020/06/22 17:40:29 http2: decoded hpack field header field "server" = "ATS/8.0.8"
2020/06/22 17:40:29 http2: decoded hpack field header field "date" = "Mon, 22 Jun 2020 09:40:29 GMT"
2020/06/22 17:40:29 http2: decoded hpack field header field "content-type" = "text/plain"
2020/06/22 17:40:29 http2: decoded hpack field header field "content-length" = "14"
2020/06/22 17:40:29 http2: decoded hpack field header field "x-frame-options" = "SAMEORIGIN"
2020/06/22 17:40:29 http2: decoded hpack field header field "strict-transport-security" = "max-age=31536000; includeSubdomains"
2020/06/22 17:40:29 http2: decoded hpack field header field "age" = "0"
2020/06/22 17:40:29 http2: decoded hpack field header field "via" = "https/1.1 uslax1-edge-bx-004.ts.apple.com (ApacheTrafficServer/8.0.8)"
2020/06/22 17:40:29 http2: decoded hpack field header field "cdnuuid" = "e319de30-a863-4933-b755-23701c259784-2214327671"
2020/06/22 17:40:29 http2: decoded hpack field header field "x-cache" = "skipped"
2020/06/22 17:40:29 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=211
2020/06/22 17:40:29 http2: Framer 0xc000338620: read DATA flags=END_STREAM stream=1 len=0 data=""
2020/06/22 17:40:29 http2: Transport received DATA flags=END_STREAM stream=1 len=0 data=""
2020/06/22 17:40:29 http2: Framer 0xc000338620: read GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
2020/06/22 17:40:29 http2: Transport received GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
2020/06/22 17:40:29 HTTP request/response done
2020/06/22 17:40:31 http2: Framer 0xc000338620: read GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=""
2020/06/22 17:40:31 http2: Transport received GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=""
2020/06/22 17:40:32 before CloseIdleConnections()
2020/06/22 17:40:32 after CloseIdleConnections()
2020/06/22 17:40:35 http2: Transport readFrame error on conn 0xc000001680: (*net.OpError) read tcp 107.182.187.28:44690->17.253.27.202:443: use of closed network connection
2020/06/22 17:40:35 Close(): <nil>
@agnivade
Copy link
Contributor

/cc @neild @fraenkel

@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 23, 2020
@agnivade agnivade added this to the Backlog milestone Jun 23, 2020
@fraenkel
Copy link
Contributor

There is no connection to close once your request is done.
If you turn on debug, you will see

2020/06/23 19:01:41 http2: Transport received GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
2020/06/23 19:01:41 HTTP request/response done

On GOAWAY, the connection will be cleaned up which will remove it from the client connection pool.

@zhangyoufu
Copy link
Contributor Author

@fraenkel I'm expecting the connection being closed by client connection pool. However, tlsConn.Close() at the last line of main() returned nil, which means that the connection is not closed at that time.

If you send HTTP request in a loop, you will see many TCP connection left in ESTABLISHED state, and never closed. The number of file descriptors will exceed RLIMIT_NOFILE soon. This is effectively a DoS vulnerability.

@fraenkel
Copy link
Contributor

fraenkel commented Jun 24, 2020 •
edited

You are correct. It seems when we processGoAway, we mark the connection dead but fail to actually close the connection.
I need to look at this closer because I would expect the readLoop to break and cause a cleanup as well.

@fraenkel
Copy link
Contributor

There is an expectation that the server side would eventually close the connection. This would break the readLoop and cause a Close to occur. However, the server side is sending a GOAWAY but is not closing the connection.
Our server normally waits 1s but I bumped the Sleep to 10s and still never received a close.

@fraenkel
Copy link
Contributor

We should probably be a bit more proactive and force close after some timeout. We can also close earlier if we know we aren't awaiting for any response which is a possibility but easily determined.

@gopherbot
Copy link

Change https://golang.org/cl/240341 mentions this issue: x/net/http2: Do not leak connections on GOAWAY

@gopherbot
Copy link

Change https://go.dev/cl/429060 mentions this issue: http2: close client connections after receiving GOAWAY

@neild neild self-assigned this Sep 7, 2022
WeiminShang added a commit to WeiminShang/net that referenced this issue Nov 16, 2022
@WeiminShang @neild
http2: close client connections after receiving GOAWAY
1e53447 
Once a connection has received a GOAWAY from the server,
close it after the last outstanding request on the connection
completes.

We're lax about when we call ClientConn.closeConn, frequently
closing the underlying net.Conn multiple times. Stop propagating
errors on closing the net.Conn up through ClientConn.Close and
ClientConn.Shutdown, since these errors are likely to be caused
by double-closing the connection rather than a real fault.

Fixes golang/go#39752.

Change-Id: I06d59e6daa6331c3091e1d49cdbeac313f17e6bd
Reviewed-on: https://go-review.googlesource.com/c/net/+/429060
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Cherry Mui <cherryyz@google.com>
Run-TryBot: Damien Neil <dneil@google.com>
@golang golang locked and limited conversation to collaborators Sep 20, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@neild neild

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
Backlog
Development

No branches or pull requests
5 participants
@neild @fraenkel @zhangyoufu @agnivade @gopherbot