x/net/http2: Transport loops forever if peer sends a graceful shutdown upon connect forever

[marianrh]

What did you do?

Running the program below causes http.Get() to loop. It seems to establish an infinite number of connections to the target server and only stops when some system or network limit is reached.
The URL in question can be accessed without problems in browsers and using curl or wget.

package main

import (
	"log"
	"net/http"
)

func main() {
	_, err := http.Get("https://www.herold.at/")
	if err != nil {
		log.Fatal("doing request:", err)
	}

	log.Print("request done")
}

What did you expect to see?

I expected the request to finish without error and request done to be printed.

What did you see instead?

http.Get() never returns. A quickly rising number of established connections to the target server is seen via ss. After a few seconds, hundreds of connections are established:

$ ss -tarp | grep -c "ESTAB .* www\.herold\.at"
322

Does this issue reproduce with the latest release (go1.12.3)?

Yes

System details

The problem was reproduced on various systems, all on x64 architecture:

• go1.11.5 on RHEL 7.6
• go1.10.4 on Ubuntu 18.04
• go1.10.4 on Ubuntu 19.04 Beta
• go1.12.3 on Ubuntu 18.04

[agnivade]

Happens when the http2 client code path is taken.

GODEBUG=http2client=0 go run arr.go
2019/04/11 14:05:06 request done

Debug logs -

GODEBUG=http2debug=2 go run arr.go
2019/04/11 14:05:21 http2: Transport failed to get client conn for www.herold.at:443: http2: no cached connection was available
2019/04/11 14:05:22 http2: Transport creating client conn 0xc000152780 to 194.146.186.138:443
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019/04/11 14:05:22 http2: Transport encoding header ":authority" = "www.herold.at"
2019/04/11 14:05:22 http2: Transport encoding header ":method" = "GET"
2019/04/11 14:05:22 http2: Transport encoding header ":path" = "/"
2019/04/11 14:05:22 http2: Transport encoding header ":scheme" = "https"
2019/04/11 14:05:22 http2: Transport encoding header "accept-encoding" = "gzip"
2019/04/11 14:05:22 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=10, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2019/04/11 14:05:22 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=10, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: wrote SETTINGS flags=ACK len=0
2019/04/11 14:05:22 http2: Framer 0xc0001b3dc0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/04/11 14:05:22 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/04/11 14:05:22 http2: Transport failed to get client conn for www.herold.at:443: http2: no cached connection was available
2019/04/11 14:05:23 http2: Transport creating client conn 0xc00032a180 to 194.146.186.138:443
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019/04/11 14:05:23 http2: Transport encoding header ":authority" = "www.herold.at"
2019/04/11 14:05:23 http2: Transport encoding header ":method" = "GET"
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=10, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2019/04/11 14:05:23 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=10, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2019/04/11 14:05:23 http2: Transport encoding header ":path" = "/"
2019/04/11 14:05:23 http2: Transport encoding header ":scheme" = "https"
2019/04/11 14:05:23 http2: Transport encoding header "accept-encoding" = "gzip"
2019/04/11 14:05:23 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: wrote SETTINGS flags=ACK len=0
2019/04/11 14:05:23 http2: Framer 0xc0002e08c0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/04/11 14:05:23 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/04/11 14:05:23 http2: Transport failed to get client conn for www.herold.at:443: http2: no cached connection was available

And then it repeats itself till the http2: no cached connection was available error.

EDIT: This is the code I used -

package main

import (
	"io"
	"io/ioutil"
	"log"
	"net/http"
)

func main() {
	res, err := http.Get("https://www.herold.at/")
	if err != nil {
		log.Fatal("doing request:", err)
	}
	defer res.Body.Close()
	io.Copy(ioutil.Discard, res.Body)

	log.Print("request done")
}

@bradfitz @fraenkel @tombergan

[bradfitz]

Thanks @agnivade for the trace.

That server looks buggy or confused.

On every request it starts a graceful shutdown and says GOAWAY (NO_ERROR), so we retry our request, per the spec.

What server software is that? It seems bogus.

I think we already have another open bug for falling back to HTTP/1 when we notice that an HTTP/2 server is buggy. Maybe somebody could find that bug. But in general, it's better for the ecosystem if we work with the other server software's author(s) and get them to fix it.

[bradfitz]

Oh, it's a Big-IP:

Server: BigIP

We've had problems with Big-IP's HTTP/2 implementation in the past. It's possible it's already fixed but that customer hasn't updated to the latest code.

[marianrh]

I tested this again (using Go 1.15.7), and the GET request returns correctly now. It seems that either something was changed in Go or the server was fixed. I'm closing this.