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

[zhangyoufu]

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]

/cc @neild @fraenkel

[fraenkel]

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]

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

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]

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]

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]

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

[gopherbot]

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