net/http: Connection to HTTP/2 site with IdleConnTimeout hangs

[flexfrank]

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

$ go version
go version go1.13 darwin/amd64

Does this issue reproduce with the latest release?

yes

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/shumpei-akai/Library/Caches/go-build"
GOENV="/Users/shumpei-akai/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/shumpei-akai/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.13/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.13/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/shumpei-akai/workspace/godebug/go.mod"
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/05/r0vdcxhd1zs_k44w77vs3k900000gn/T/go-build031355801=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Access a HTTP/2 web site with IdleConnTimeout multiple times.

package main

import (
	"log"
	"net/http"
	"time"
)

func get(client *http.Client) {
	log.Printf("start get \n")

	res, err := client.Get("https://twitter.com/")
	if err != nil {
		log.Fatalf("error get: %+v", err)
	}

	defer res.Body.Close()

	log.Printf("get finished: status=%d\n", res.StatusCode)
}

func main() {
	t := &http.Transport{
		MaxIdleConnsPerHost: 1,
		MaxConnsPerHost:     1,
		IdleConnTimeout:     time.Duration(1) * time.Second,
		ForceAttemptHTTP2:   true,
	}

	client := &http.Client{
		Transport: t,
	}

	get(client)
	time.Sleep(2000 * time.Millisecond)
	get(client)

	log.Println("success")
}

What did you expect to see?

Both connections should successfully return.

What did you see instead?

The first connection succeeds but the latter one does not return.

Log:

2019/09/19 12:39:08 start get 
2019/09/19 12:39:08 http2: Transport failed to get client conn for twitter.com:443: http2: no cached connection was available
2019/09/19 12:39:09 http2: Transport creating client conn 0xc000076d80 to 104.244.42.1:443
2019/09/19 12:39:09 http2: Transport encoding header ":authority" = "twitter.com"
2019/09/19 12:39:09 http2: Transport encoding header ":method" = "GET"
2019/09/19 12:39:09 http2: Transport encoding header ":path" = "/"
2019/09/19 12:39:09 http2: Transport encoding header ":scheme" = "https"
2019/09/19 12:39:09 http2: Transport encoding header "accept-encoding" = "gzip"
2019/09/19 12:39:09 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2019/09/19 12:39:09 http2: Transport received SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=65536
2019/09/19 12:39:09 http2: Transport received SETTINGS flags=ACK len=0
2019/09/19 12:39:09 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=1032
2019/09/19 12:39:09 get finished: status=200
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=7143 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\xff\xec}\xfb\x9b\x1bű\xe8\xef\xfbW\x8c\x87\x9cE\x1bk\xf4\x96V\xb2W\xeb\x03\x06\x12\xee\xe5ub'9\xf7\x1ag\xbfѨ%\x8dw4#fF\xbbހ\xbf\xcf\xda\x05\xe2\x17\xb1!`\x87\x00\x01\x9b\x97\xb1c\x03\x87\xe4`0\x8e\xff\x18Y\xeb\xf5O\xf9\x17nU\xf7<z\x1eZ\xcd\xee\x1a'\xf7|6\x89v\xa6\xa7\xbb\xba\xba\xaa\xba\xba\xba\xba\xba{n\xd7\x13\xcf\xef?\xf8\u007f^xR\xe8\xd8]m~j\x0e\xff\b\x9a\xac\xb7\xeb\xe2\x11Y\x14\x9a\xb2-K\x96b\xaa\r\"\x99\xa4\xd9WHS\x92\x15[5t\xe9\xa5>铺h\x9b}\"\xceO\t\xc2\\\x87\xc8M|\x10\x84\x04?s]b˂ґM\x8b\xd8u\xb1o\xb7\xa4\xaa\xc8J\xc3G\xac\xb1g\v\x82n\xe8\n\xd6\xd1\xfbY\xa5rD^T\xf6\xaf(\xadg\x8a\xb39刲\xbb]\xaf{\x05\x04aW\xab\xafS\xbcR3//\xabz\xd3X\xce" (6887 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=8240 data="\x02\xc9/g\xc9K\xa4\xe98\x92\xdd3N@Li$|\xe0\x13\x15g\xeaI\x8b\xc0Pd\x9b\xb4\xc1\xa0f\xf2,\x84\xca9B\xbe\xfe\xc9\xfbw\xffz\x89F\x9e]\xf2<g}-\x19\x96h\xebZa\xc0\xc8]\xa7\xbd\x9e\xa5\x9c\x18\x9a\x10O\x02\xc7v\x8f\x1b\x83\xc2\xeaD\x8c\x91\x96\xf9M\xf5\xc9\xe8\xe4\xa9{\xef~⨐1\xf6\xac\xe1\x1c\xd9Aa\xb3\x9d\x19\r\xd2l\xacLd\a\x8b\x1bpM[\xf7\xc0\\֨\x97\xfa0\x9ex\x89\xf4M\xb2\x8c\xbe\x89\xfb\x19\x9cĦ\xe5\u0530\xe0m\x19\x91\x1b\xf4\xa0ٺ(\xe5QZewЊ\x9bE\xd0/[\xe3\xa6\xffn\x1b=\fkB\xa8S\xdbg#\x85\xc2\xf3/B\xd3\x1dRʫj\x81\x1dr\xe5\x13\xcei@<\xc9\x18\xc1\x18\xb9vD&'\xd0\x10\xfa\x81\xa1\xa8\xee\xe0y\xd4\x0e\xea\x017\xd3$jRܩ\x86Ǯο\xb3\x1dQ,r\xcdI\xc7âl7x\xcf=\x8a\xd90i\x86" (7984 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=1001 data="-8\xb7ih\x0f\xbc\xa66\xcd;\xe5\xc4\xff0\xa94lٮ\x01\x859\x97Q\xf1\x03d\xbf\xabg\xb3\xeaG|hJ;\x15v\xd04\x9b6\x15\"\xa6\xf9\xe8S\x1e\xf3,\x88Gw5t\xbd\xc3\f,\xcb\xdc\x19o\x91\x17ޫ.=\x88\x81~܂\xa13\x87\xd4\xc8\xc4\xe3\xbeYiW.̬\x80\x14\xbf\xc5\\\x9d\xba\xfc\x9b\xeeǵ\xf38\x11\xb0\x1fh\x0e\v\x05\xff\x952ucP\x1b@6\xf3\xee'x\x1f\xa7\xa0\x0fi\xa1H2\xfb.1\x1c.{UG\x02#3Z\xd2\af\xc2p\xb4\x11.\xbd\r0\xffQ|\xfb\x0e\x95\"{Qd\xa6\xf2\xe8\x1d8\x85\tt\xb8p\x99G\xe6\x00\xdd؊\xc0\xe2\x06q-\xe5\xc95\xf0Y\x01\x9b5K\x89\xa5ͦ'4\xb4֠:\xae?^\x18\xdd\xc1\x89\x84\xb9\x9e\xe8\x8bA\x90\xa3\xf0j\x98b8\\\xb7\xe9贫\x11Ɲ7t\x02(=\xef\x10װp\xe6D\xfd\xd3\f\x01\x97\\\x1c\a" (745 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=7134 data="\\WgF\x01\xa3Nr\x1d51\xf9\x1d\x1b\xb1\xa2\xd2r\x11\xcdQ\x92qh9ϐ8U\u007f\xe7\xec0\xbf\xb8\x00\xafdS$'H\xb5;\xd7K0\x0f%\xbaN,7\x87\xc7G}\t\x92\xbc\xb16\xc2[k\xa9\xc0b2\x94Nt\xae\x15Ճ~֠\xeaHp\xd2(\x16\rm\x1c\xae\xd6i\xee=H\x83\xdbE\x1b\xe7\xddq\x8e`G\x10Q\xb4\xe4\xf9\xdc_\xceP\xa7O\x80\xdd&ڨO\x1cb\x13-\x19\xf6\x934\xda\u05c8\xc4Q^y\xd4\xf1T:x\xa5\x94\xe9{\xd9\xc2(|p;ߦX\x18\x8f+\x15\xae\xc3Q\xb8\xb5q\x1b5\r\xf0\xefV\xa0i\xb8\xb5y\x11\x8a\uf86eA\x9d\xb4\xf7m\xc3\x05\x12O;j\x06\x8e\x81n\x03\x19\x1a`\xd1\x1dA\xc4=\x02@\\\xd2\xf5ʈ\x14\xe2\x16\x8b\xd4t\xa9:\xa9|\x827\xe3\x12\x18\xea\x18\xb6\x11\x1dʁ\x0eU\xf2\xb5\xe2\x1a\x1f\xbeB\x9b\xe7\xe1\xdf\xf2\xa6\xba\xeaTY\xfdca\x1c" (6878 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=8240 data="9h,\xa3<\x839ʳ\x9ck\x83\xa35\xdb\xec\x96\x12\xf1>\xcd\x12\xbbL\xcbF\x8c\bY\xe3Ć\"\xaa\x8d\xcch\xa7hҡc:3\x05G\x92\x1d@$\xc4x=\x12\xa5\xe7\x10#Nv\xe5X\xc1(\x81\xaa\xc8\x02\xf2\xf0\x1d\n\xbf\x8c0\x9c\x90\xfav\x9cJ\xa5\x89\xafG4\\ӣ\x88\xb3)5y\x90&\x12'\xb7Z\xa8q\x1a\xf5\x81\x14^(0_,\x91\xa8\xfeM=c2\xa6S\xf5\x83&\xe7\xf4\x02sm\f\x143\x14\xf4\x1b\xd0\xf0]Ê\xc6#\xc0\x84\x950\xf8b\x8c\xa4:\xd3A;-ŲL\x1b\x0f\xbdrB:\xab]\x95\xe8\xa5P\x01\"\x8b\x18\x16\x85\xed\xe0TJp|\xe2(\x9dyc\x99{@\xdb*\x89Æ\xc5܌C\xe6c\x189\xd58\x9a\xa4\x87Qq\x89X\"\xb1\xb6\xfd\x8e'\xf5Z\xae.}\xcd3\xa4\xadl߽\xbc\xfd\xae\xba/n\xe8\xe5>\xebP[\xe7o\xa9\x85\xa2\xcc(\x82^\xc7z\x89\xb4\x00." (7984 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=1010 data="\xeb\x15Ц\xbf\xdb>\xb7}f{\xcdں\xbcuq\xfb\xec\x96~x\xff\xac\x1fp\ue83cj=\x1f\xb9\xb4\xe9\xc9P\x97+VZ;4\x84\xc7Ȑ\xc8\xd5\xd7<\a\xae\xe9\b@T\x9e\x96\x99k'r\xf0\x00\x84\xdf11>\xb4\xc1&\xda\x1dT0&\x81\xfd\xfc\xa4\xb1\xb6f\xc2J\xad\x05hb\xf6\xc6\r\x03\x8c\xda\f\b\xc7\x1c\x04\x9d\xc9\xc58\x03\u07b4\xcd\x1d\x89\xfcs\x8f&\xf2\xc4z\xa9\x85[]\xdfSy\xe8\x8fljS\x89C\xc5ۯ\xba*\x85\xfb\xab\v\"N\xd0\xf3i\x95Q\x13\xfe\x1as\xa4 \x86\x8d\"\xabgX\xd3\x17,\x849\u007f\x92\xf9\xd4Z:\x96L2\xb9L\xfe\xa5!\xd3'3L\xf9%\x97\xa6\x0f\xb5]\xc8\xee,\f\r&F\a\xc7\x1c\t\xa3\xe0\x18\xe2^\x10\x8d\x1eK\x1fM\xe1#\xf9}{\xb7\x91\xa57d\xef\x873\xdf\x035`\xa8\xa8\x89ʑ\xa3\xbf\v\xaaU\x9c\xc3\x11.\xb1\xce*PZ\xaf:C*\xf06y" (754 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=7125 data=".+\xfa\x87%\xc1T\xaf\x81\x05*\x835Fʸ$@\xfc\x14\xa7`zJ\xee\xd1B\x9e(\x95:F\x9d\x1b\x84[-\xe5\xa6\x17\x84\x16\x9a\xab\xd4-\x14\x96a\x90\xf6\x13r\xaf\x16\n\x8f\x0f\tGDԋ\xfe\xab\xc1\xaeDZ\xab5\x16\x9d>]\xa4\xd4N&m\xa7\x1aY=\xa6xf`0L\b\xf2\xb6\x895z\x16G\xc0_L1ő\x18#\x15\xf1:V\xc9\xd2\xddr\xa1\x12UI\xc9dO\xe9\xe2\x96<\x92\x8c\xd9S\xa3\x8e\"琘\xb3b\x13\xb4\x17ۊ\xf5\x1f\xa7_\x1b44#\x05▐I%\xcf\xf5a\xe1GD\xef6\x94\x8dT\xa4\xc2\x02\xa6\xe1x\x19\x89\xfc}\xe5\n\xbe{v\xf3\xe6\xe6\xf7\x9b?m^\x87\xff\xde\x11q\xb4\xc8W\x87W\xfa\xf8\x83\x01\x98m\x98\x93\xc0\xaa\xab\"\xf0\xb6\xefWf\x1c\xdc\x1bx\x9c\xbb\x8c:\x91\xbe\xb7n\x9cW\xa9]\x17\xa0y\f\x81\x1f\xf7\tl\xa0/\xc0?\xe2E4E\x84\x9e\x9au\x8c\xed" (6869 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=8240 data="\xdd\xeb\xcb\xf2!\xdb\xed\xf8\x04P\x01\x99n\xce\xec\xa8\x11\x1f\xa9v\xe7\xf2\xfaw7js\xdf\xd4*g\u05ff\xba\xc5\x12F\xdfy\xf9\xe4\xc9\xfa\xef\xffb\xb9z\xcf\xd4濩\xcd˛a\x136\xdd\x11\xb1e\xe1\xf7&\xc6\xea\x1b%W\xc6\vK\xa6\x83L\x8fL\xcb\u007f\xdf\xe3V\xb9P\xa4\x9a\xc3(\x84\x19խ\nﴬh\x83\x12\xd5Vn@\xa0\v\xb8\xfa\xce\x00\xbf\xc0\xea\xbc\xf4h\xbač>?\xfd\xfc\xc4\xf2\xbdeyY!\x165;cfP\x86\x10\x0f\b\xf6\x10\xfb\xdec_]\xa6\x1cR̕;mǍ\xd0\xfc\xbf\xa7\xa8&\x92C\xce\xff\xdc_\xfaŦ\xf2\xdc\x1eԂ^}w\xa96\xf7\xd9\xfa\x17\xf7js\xb7X\x8e2yDAO\x1dk\x05S\xa7\x1a5\xdda\xec\x92\nҲ\x1fSѿ\xe4j\xec\xdfѰ/\xed\x88\xe5E\x14\xf8\xda\xe8\xfb\x9d\xb5\x12@\xbf\\\xec\x91,So\xe5ׁ\x80\x9fs\x8a8\xc4\xf6\xc8\xf6cQ" (7984 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA stream=1 len=1019 data=":\x85\xf1\x11\xf7\x10\xed\xe5H\xabb\xb1m\xf1>\x847\x04o\xea*\xc4>\xc8?\x17\xf0\x903Z/\xba1\x82\x9eC\x00\x0f\x1d\xd9\xfb\xdbն\xf2\xf4ѷ\x19\xd32\xabN\xe6nz9\x85\x10\xf4a8\x8b\xe5\x96\xdarL\xf1e\xa2\xfd\x05\xe5\xa9\x12\xb8'd\xbbY+\xee\xf0\xf3\xb1\x0fGv\f?\x0f\xdb\b\xa6\x04\x82\xacs\x88Π0M\x98\xf4Ȓo7C\x18m\xa1\xa6-\x8f\f$\xb7~\x89D.\x88\xcb<\x8e\xa7\xb1\xa5\x90Gq\"8=$\x9e\x99\xc4V(a\x051\x91\xedj\xf9ecq\xf5\xcc\xca]m\xe5\xfa\xcaO+\xf7\xe9\xce'\xcfߤ\xf8\x99\x98V(\x88\xed6\x01\x9d\xe9:\x88\x8edf\xff\u007fQa%(z\xf1Ջ\v/\xbeyq\xe3\xc5\xf9\x17\xb7\xe0\x9c\x17_\xc9?\x15֫6\x84!}d\x03S\xe2\xf6]\xaf\xb3v<\xde\x19X\xf9\xefG\t⪌\x95\xff\n\xfb}\x95\x81\x16N1`\xc3\xf5\xb5\xaa<W" (763 bytes omitted)
2019/09/19 12:39:09 http2: Transport received DATA flags=END_STREAM stream=1 len=4908 data="\x13\xa9\x91\x06\x8fE\x8b:\xde\v\u007f\xf1\xdaƕ\xef6.\xc9\xef\a=\x0f\x98\xa8\x9b\x06g\xd1l\xf7\x89`?\xa4\x9d\xb4X\n\xebU|D\xc9SF\xee^\xa5\xff?^\xfemY\x9eA \x9e\xacѐx֎\xf2\xd0搓\xf7\x90\x9d/\xc8\xc7u\xa7\xe0\xdc)z\xee(\x9e1u\x12\xb9s\x04\xa5<N%G\xdc4\xa62\x93Ae\xa8\x02r\x152?R\x11\tLS\xa3\xf4dlh)\x13\xee^K\xf5\x85\xe2\xec\x81\x19\xad\x9f\xf5O\xdb@\x13\xe9\x13\xb8!\xef߷/.\xe3\x11\xed\x8a\xca\u07b8\x84\xdd\xf6\xe6\xa3\xed\xed\x04(\x9b\x12q\xb3.vL\x05\x98M\x90\x85\xa1\xdfB\xaew\x10[\x96\xd6?)*\x13\b;\x06q\x8f\xfb\xb6\n\x83^}\xe7\x9e\xc23\x88;\xe6e\x06:\x16:? \x86V\xfdR\xa0Tl;\xe4\xcd\b,\x8f\xd4\x1fg\xee\xbf|zI\xfaJI\xa2#-I,\x14\xaeӇ\x89\x9eCyd`;\x12\x16vj" (4652 bytes omitted)
2019/09/19 12:39:10 http2: Transport closing idle conn 0xc000076d80 (forSingleUse=false, maxStream=1)
2019/09/19 12:39:10 http2: Transport readFrame error on conn 0xc000076d80: (*net.OpError) read tcp 10.210.45.42:55625->104.244.42.1:443: use of closed network connection
2019/09/19 12:39:11 start get 
2019/09/19 12:39:11 http2: Transport failed to get client conn for twitter.com:443: http2: no cached connection was available
2019/09/19 12:39:11 http2: Transport failed to get client conn for twitter.com:443: http2: no cached connection was available

[toothrot]

I am not sure if ForceAttemptHTTP2 does anything when no Dial, DialTLS, DialContext, or TLSClientConfig is specified. From the documentation:

// ForceAttemptHTTP2 controls whether HTTP/2 is enabled when a non-zero
// Dial, DialTLS, or DialContext func or TLSClientConfig is provided.
// By default, use of any those fields conservatively disables HTTP/2.
// To use a custom dialer or TLS config and still attempt HTTP/2
// upgrades, set this to true.

And the check here:

go/src/net/http/transport.go

Line 353 in cc8838d

if !t.ForceAttemptHTTP2 && (t.TLSClientConfig != nil || t.Dial != nil || t.DialTLS != nil || t.DialContext != nil) {

Regardless, I believe there is an issue here. This fails consistently for me for the domain in your example, and others that I tested.

I added some tracing, and found the following on error:

2019/09/19 18:23:28 start get 
2019/09/19 18:23:28 getconn "www.google.com:443"
2019/09/19 18:23:28 ConnectStart
2019/09/19 18:23:28 ConnectDone
2019/09/19 18:23:28 TLSHandshakeStart
2019/09/19 18:23:28 TLSHandshakeDone
2019/09/19 18:23:28 gotconn {Conn:0xc0000b6700 Reused:false WasIdle:false IdleTime:0s}
2019/09/19 18:23:28 get finished: status=200 proto="HTTP/2.0" close=false
2019/09/19 18:23:30 start get 
2019/09/19 18:23:30 getconn "www.google.com:443"
2019/09/19 18:23:30 getconn "www.google.com:443"

Without IdleConnTimeout set, it behaves as expected:

2019/09/19 18:26:13 start get 
2019/09/19 18:26:13 getconn "www.google.com:443"
2019/09/19 18:26:13 ConnectStart
2019/09/19 18:26:13 ConnectDone
2019/09/19 18:26:13 TLSHandshakeStart
2019/09/19 18:26:13 TLSHandshakeDone
2019/09/19 18:26:13 gotconn {Conn:0xc000075c00 Reused:false WasIdle:false IdleTime:0s}
2019/09/19 18:26:13 get finished: status=200 proto="HTTP/2.0" close=false
2019/09/19 18:26:15 start get 
2019/09/19 18:26:15 getconn "www.google.com:443"
2019/09/19 18:26:15 gotconn {Conn:0xc000075c00 Reused:true WasIdle:true IdleTime:2.002054258s}
2019/09/19 18:26:15 get finished: status=200 proto="HTTP/2.0" close=false

The idle connections are pretty nuanced, especially with connection sharing in HTTP/2, so let's ask @bradfitz.

[flexfrank]

I confirmed that ForceAttemptHTTP2 does not affect this issue.
When the destination server supports HTTP/2, connections hang.

[fraenkel]

The second request is handed the idle connection which has been marked dead.
When the http2.Transport returns with an http2.noCachedConnError, only the idle connection is removed. However, the http.Transport believes there is still a connection in the connsPerHost that can be used which isn't really true.

[gopherbot]

Change https://golang.org/cl/196665 mentions this issue: net/http: Remove http2 connections when no longer cached

[bradfitz]

@fraenkel, was this a regression from Go 1.12? Should we backport this to Go 1.13.x?

[bradfitz]

@gopherbot, please backport to Go 1.13.

(I'm assuming.)

[gopherbot]

Backport issue(s) opened: #34498 (for 1.13).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[fraenkel]

@bradfitz It's a regression. It is a bit difficult to come up with a good set of tests to cover the connection management between the http and http2 side.