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

x/net/http2: connecting to non-compliant HTTP2 server returns Client.Timeout exceeded; fallback to HTTP/1? #20979

Open
tkng opened this issue Jul 11, 2017 · 30 comments
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@tkng
Copy link

tkng commented Jul 11, 2017

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

go version go1.8.3 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/tkng"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.8.3/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.8.3/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/z1/nc5xfnrs71g2zxr_chmshx3h0000gp/T/go-build993898931=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

Following snippet code should be enough to reproduce the problem.

https://play.golang.org/p/PmZWp6NJlq

If I disabled HTTP2 by the environment variable GODEBUG=http2client=0, then I see no error. Hence I guess this issue is related to HTTP2. This is might be the same as #13959, but I'm not sure.

Also, I'm not sure this is the problem of golang's HTTP2 client library, or the problem of server side. (In most case, HTTP2 client works nicely.)

What did you expect to see?

I can connect to the server (by http2, or falling back to http1.1). At least, I want to see a more suggestive error message.

What did you see instead?

I saw an error message like following:

2017/07/11 15:22:01 http.Get failed, error: Get https://precious.jp: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
@odeke-em
Copy link
Member

@tkng could you please try with the latest Go and see what the result is? Perhaps the bug was fixed in Go1.9.

@odeke-em odeke-em changed the title Go's http client cannot connect to a HTTP2 server, returns Client.Timeout exceeded x/net/http2: connecting to some HTTP2 server returns Client.Timeout exceeded Jul 11, 2017
@odeke-em
Copy link
Member

I've made a bug repro at https://github.com/odeke-em/bugs/blob/master/golang/20979/main.go or

package main

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

func main() {
	res, err := http.Get("https://precious.jp")
	if err != nil {
		log.Fatal(err)
	}
	if res.Body != nil {
		defer res.Body.Close()
	}
	if !statusOK(res.StatusCode) {
		log.Fatalf("res: %s", res.Status)
	}
	io.Copy(os.Stdout, res.Body)
}

func statusOK(code int) bool { return code >= 200 && code <= 299 }

which when run seems like an infinite loop of renegotiating headers, until I hit Ctrl+C

$ GODEBUG=http2debug=2 go run main.go
2017/07/11 01:25:03 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:04 http2: Transport creating client conn 0xc42014c1a0 to 202.238.151.220:443
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:04 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:04 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:04 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:04 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:04 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:04 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:04 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:04 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:04 http2: Framer 0xc42044d0a0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:04 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:04 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:05 http2: Transport creating client conn 0xc42014c4e0 to 202.238.151.220:443
2017/07/11 01:25:05 http2: Framer 0xc42044d500: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:05 http2: Framer 0xc42044d500: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:05 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:05 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:05 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:05 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:05 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:05 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:05 http2: Framer 0xc42044d500: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:05 http2: Framer 0xc42044d500: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:05 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:05 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:05 http2: Framer 0xc42044d500: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:05 http2: Framer 0xc42044d500: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:05 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:05 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:06 http2: Transport creating client conn 0xc42014c820 to 202.238.151.220:443
2017/07/11 01:25:06 http2: Framer 0xc42044d960: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:06 http2: Framer 0xc42044d960: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:06 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:06 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:06 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:06 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:06 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:06 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:06 http2: Framer 0xc42044d960: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:06 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:06 http2: Framer 0xc42044d960: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:06 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:06 http2: Framer 0xc42044d960: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:06 http2: Framer 0xc42044d960: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:06 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:06 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:06 http2: Transport creating client conn 0xc420488340 to 202.238.151.220:443
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:06 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:06 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:06 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:06 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:06 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:06 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:06 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:06 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:06 http2: Framer 0xc4201481c0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:06 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:06 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:07 http2: Transport creating client conn 0xc42014cb60 to 202.238.151.220:443
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:07 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:07 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:07 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:07 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:07 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:07 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:07 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:07 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:07 http2: Framer 0xc42044ddc0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:07 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:07 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 01:25:08 http2: Transport creating client conn 0xc42014cea0 to 202.238.151.220:443
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 01:25:08 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 01:25:08 http2: Transport encoding header ":method" = "GET"
2017/07/11 01:25:08 http2: Transport encoding header ":path" = "/"
2017/07/11 01:25:08 http2: Transport encoding header ":scheme" = "https"
2017/07/11 01:25:08 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:08 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 01:25:08 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 01:25:08 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: wrote SETTINGS flags=ACK len=0
2017/07/11 01:25:08 http2: Framer 0xc4202288c0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:08 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 01:25:08 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
signal: interrupt

/cc @tombergan @bradfitz

@tkng
Copy link
Author

tkng commented Jul 11, 2017

@odeke-em thanks for your advice, I tried the latest golang master branch.

> go version
go version devel +6f83b75 Mon Jul 10 20:09:00 2017 +0000 darwin/amd64

but, unfortunately, I still see the same error message as above.

2017/07/11 17:05:57 http.Get failed, error: Get https://precious.jp: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

@bradfitz bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 11, 2017
@bradfitz
Copy link
Contributor

bradfitz commented Jul 11, 2017

What software is precious.jp running? It's sending a GOAWAY to us in response to our first request:

ante:~ $ GODEBUG=http2debug=2 go run h2get.go
2017/07/11 11:40:41 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 11:40:41 http2: Transport creating client conn 0xc4200761a0 to 202.238.151.220:443
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 11:40:41 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 11:40:41 http2: Transport encoding header ":method" = "GET"
2017/07/11 11:40:41 http2: Transport encoding header ":path" = "/"
2017/07/11 11:40:41 http2: Transport encoding header ":scheme" = "https"
2017/07/11 11:40:41 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 11:40:41 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 11:40:41 http2: Framer 0xc420164380: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 11:40:41 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:41 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote SETTINGS flags=ACK len=0
2017/07/11 11:40:42 http2: Framer 0xc420164380: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 11:40:42 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 11:40:42 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 11:40:42 http2: Transport creating client conn 0xc4200764e0 to 202.238.151.220:443
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 11:40:42 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 11:40:42 http2: Transport encoding header ":method" = "GET"
2017/07/11 11:40:42 http2: Transport encoding header ":path" = "/"
2017/07/11 11:40:42 http2: Transport encoding header ":scheme" = "https"
2017/07/11 11:40:42 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:42 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:42 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 11:40:42 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: wrote SETTINGS flags=ACK len=0
2017/07/11 11:40:42 http2: Framer 0xc4201647e0: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 11:40:42 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 11:40:42 http2: Transport failed to get client conn for precious.jp:443: http2: no cached connection was available
2017/07/11 11:40:42 http2: Transport creating client conn 0xc4202901a0 to 202.238.151.220:443
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 11:40:42 http2: Transport encoding header ":authority" = "precious.jp"
2017/07/11 11:40:42 http2: Transport encoding header ":method" = "GET"
2017/07/11 11:40:42 http2: Transport encoding header ":path" = "/"
2017/07/11 11:40:42 http2: Transport encoding header ":scheme" = "https"
2017/07/11 11:40:42 http2: Transport encoding header "accept-encoding" = "gzip"
2017/07/11 11:40:42 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:42 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=32768, MAX_HEADER_LIST_SIZE=32768
2017/07/11 11:40:42 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 32768]
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: wrote SETTINGS flags=ACK len=0
2017/07/11 11:40:42 http2: Framer 0xc4203dd180: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2017/07/11 11:40:42 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""

That looks busted on their side. If they didn't like something about our request, they sure didn't say why.

We write:

2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=33
2017/07/11 11:40:41 http2: Framer 0xc420164380: wrote SETTINGS flags=ACK len=0

And then we read:

2017/07/11 11:40:42 http2: Framer 0xc420164380: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""

Maybe their implementation expects the SETTINGS ACK immediately after the initial SETTINGS frame (requiring a full RTT), instead of the the WINDOW_UPDATE + HEADERS in the middle? But the spec says in http://httpwg.org/specs/rfc7540.html#rfc.section.3.5:

To avoid unnecessary latency, clients are permitted to send additional frames to the server immediately after sending the client connection preface, without waiting to receive the server connection preface.

So it does look like their server is at fault.

/cc @tombergan

@bradfitz
Copy link
Contributor

It works in Chrome, though.

What's the difference?

@bradfitz bradfitz added this to the Go1.10 milestone Jul 11, 2017
@tkng
Copy link
Author

tkng commented Jul 12, 2017

@bradfitz thanks, your comment is helpful. Unfortunately, I don't know what kind of software is used. I'm just a developer of an image resizing proxy with Golang, and found that I can not access to the site through HTTP2 via Golang. I'll try to contact them, ask what software is used there.

But there's little hope to obtain detailed information. (I don't have a direct connection to an engineer.)

@bradfitz
Copy link
Contributor

@tatsuhiro-t, do you happen to have any idea here? Either of what software that site runs, or what their server might not like about Go's HTTP/2 client?

@tatsuhiro-t
Copy link

It looks like the server does not like SETTINGS_MAX_HEADER_LIST_SIZE. It smells like a bug of the server side.

@bradfitz
Copy link
Contributor

@tatsuhiro-t, oh, indeed! Thanks.

It accepts a value up to 32KB, but one byte over that and it's rejected:

bradfitz@gdev:~/src/golang.org/x/net/http2/h2i$ h2i -settings=MAX_HEADER_LIST_SIZE=32768 precious.jp
Connecting to precious.jp:443 ...
Connected to 202.238.151.220:443
Negotiated protocol "h2"
Sending: [[MAX_HEADER_LIST_SIZE = 32768]]
[FrameHeader SETTINGS len=18]
  [MAX_CONCURRENT_STREAMS = 100]
  [INITIAL_WINDOW_SIZE = 32768]
  [MAX_HEADER_LIST_SIZE = 32768]
[FrameHeader SETTINGS flags=ACK len=0]
h2i> 
bradfitz@gdev:~/src/golang.org/x/net/http2/h2i$ h2i -settings=MAX_HEADER_LIST_SIZE=32769 precious.jp
Connecting to precious.jp:443 ...
Connected to 202.238.151.220:443
Negotiated protocol "h2"
Sending: [[MAX_HEADER_LIST_SIZE = 32769]]
[FrameHeader SETTINGS len=18]
  [MAX_CONCURRENT_STREAMS = 100]
  [INITIAL_WINDOW_SIZE = 32768]
  [MAX_HEADER_LIST_SIZE = 32768]
[FrameHeader GOAWAY len=8]
  Last-Stream-ID = 0; Error-Code = NO_ERROR (0)
h2i> 

@bradfitz
Copy link
Contributor

The precious.jp server is probably misinterpreting the meaning of SETTINGS_MAX_HEADER_LIST_SIZE (http://httpwg.org/specs/rfc7540.html#SETTINGS_MAX_HEADER_LIST_SIZE) and thinking that it's how much the client will send, whereas it's actually the client telling the server how much the client is willing to receive. The server is probably confused and thinking, "No way, I'm not going to allocate more than 32KB for you!".

We need to figure out which server this is and fix the interop problem.

@tkng
Copy link
Author

tkng commented Jul 12, 2017

@tatsuhiro-t @bradfitz thanks for great progress.

Though I haven't receive any replying from precious.jp yet, I found that the specification of netty seems consistent with the current situation. According to the reference manual, there's a method maxHeaderListSize in DefaultHttp2HeadersDecoder class. If the value of parameter max is greater than the value of parameter goAwayMax, then a GO_AWAY frame will be generated.

@tkng
Copy link
Author

tkng commented Jul 12, 2017

The reply came from precious.jp. According to that, they use BIG-IP, but they don't want to reveal the version. Nothing special about setting.

I asked them to check their setting which related to SETTINGS_MAX_HEADER_LIST_SIZE if possible.

@tkng
Copy link
Author

tkng commented Jul 14, 2017

There's no reply from precious.jp from 2 days ago.

By the way, I checked whether other http2 clients can access to precious.jp.

Name Version Result
Google Chrome 59.0.3071.115 OK via HTTP2
Safari 10.1.1 (11603.2.5) OK via HTTP2
Firefox 54.0 OK via HTTP2
curl (compiled with HTTP2 support) 7.54.1 OK via HTTP2
golang 1.8.3 NG

Since the most of major browsers can access to precous.jp, I'm happy if golang's http client library can handle the site.

Though it's just an idea, is it possible to fallback to HTTP/1.1 when a server throws a GO_AWAY frame?

@bradfitz
Copy link
Contributor

Sending a GOAWAY frame is a totally reasonable thing to do. If we fell back to HTTP/1.1, we'd need to do it only if the GOAWAY's LastStreamID=0.

But I'd also like to fix this in Netty.

Hey netty-http2 authors, @yschimke, @atollena, @caniszczyk, @nhnFreespirit, it seems that Netty-http2 might be misinterpreting the meaning of SETTINGS_MAX_HEADER_LIST_SIZE and improperly rejecting clients. Go, for instance, says we're cool with up to 1MB of headers in the response, but Netty says "1MB? Whoa whoa, that's more than the 32KB I want to allocate for you, so GOAWAY." Whereas it should think, "1MB? Yeah whatever, my internal hpack buffer for you is way smaller than 1MB. You'll be fine with my little responses."

@bradfitz
Copy link
Contributor

/cc @Scottmitch @normanmaurer

@bradfitz
Copy link
Contributor

Is there another Netty server directly facing the Internet?

netty.io is behind Cloudflare's "cloudflare-nginx" http2 implementation.

@tombergan
Copy link
Contributor

Sending a GOAWAY frame is a totally reasonable thing to do

Is it? That sounds like a painful workaround for a broken server that will helpfully soon be fixed.

But I'd also like to fix this in Netty.

Are we sure the server is using netty? This comment says they're using BIG-IP, which is a load balancer from F5.

Also, I'm not sure this is a bug in netty, at least not in the current version of netty. Here's the code that processes a SETTINGS frame:
https://github.com/netty/netty/blob/cf26227c6ca6cf405d2b4140e47548a31da1b305/codec-http2/src/main/java/io/netty/handler/codec/http2/Http2Settings.java#L235

MAX_HEADER_LIST_SIZE = 2^32-1, which looks fine.

According to the [netty] reference manual, there's a method maxHeaderListSize in DefaultHttp2HeadersDecoder class. If the value of parameter max is greater than the value of parameter goAwayMax, then a GO_AWAY frame will be generated.

In my reading of the netty source, that code triggers only if an actual HEADERS frame is received where the size of the HEADERS exceeds goAwayMax. But Brad's example from earlier shows that we receive GOAWAY immediately after sending SETTINGS.

@tombergan
Copy link
Contributor

@bradfitz, do you have any contacts at F5?

@bradfitz
Copy link
Contributor

I have an ex-F5 contact I can ask for referrals. Unfortunately https://f5.com/products/big-ip is not served with http2 so I can't verify.

Apologies if I was assuming Netty incorrectly. I might've misinterpreted the comment above.

@Scottmitch
Copy link

in response to #20979 (comment) ... Netty does not do any immediate allocation as a result of receiving SETTINGS_MAX_HEADER_LIST_SIZE and as referenced in #20979 (comment) the values are a limited based upon the values in https://tools.ietf.org/html/rfc7540#section-6.5.2, and in the case of SETTINGS_MAX_HEADER_LIST_SIZE we limit to 0xffffffffL. Any settings we receive are applied to limit capabilities of the remote endpoint [1]. Based upon the issue description I don't think Netty would exhibit this behavior.

[1] https://github.com/netty/netty/blob/4.1/codec-http2/src/main/java/io/netty/handler/codec/http2/DefaultHttp2ConnectionDecoder.java#L410

@tkng
Copy link
Author

tkng commented Jul 19, 2017

Sorry for my wrong comment about Netty caused confusions.

If my understanding is correct, precious.jp (the site we have the problem now) runs with Big-IP. However I don't have evidence about that, since the HTTP server hides the name of the software and version of the software.

Unfortunately, I don't have a reply from site owner for several days, there's little hope that reply will come.

Sending a GOAWAY frame is a totally reasonable thing to do

Is it? That sounds like a painful workaround for a broken server that will helpfully soon be fixed.

Sadly, I don't think we can hope the server will soon be fixed. Even contacting them is hard.

Put it aside, IMO it's basically a good idea for smooth transition to downgrade a protocol to an old one if a new protocol doesn't work. (If there's no security issue.)

Whether the standard library should automatically downgrade the protocol that is using is controversial, however I hope that the programmer is possible to downgrade if it's needed.

Current implementation doesn't allow that behavior to developers, since it doesn't return any error message (it seems not returns infinitely, or returns with timeout error if timeout is set). I think there is room for improvement for this aspect.

I hope golang's HTTP library to return an error message when the HTTP2 protocol was used and it received GO_AWAY frame before received anything.

@bradfitz
Copy link
Contributor

bradfitz commented Aug 3, 2017

We just got another case of this in #21301 (closed as dup).

But in #21301 you can see the same behavior but can also see Set-Cookie: BIGipServer~CorpWeb~pool-corpweb-prod in the HTTP/1.1 response headers, further implicating F5's implementation.

@mnot, do you have HTTP/2 contacts at F5? We have an interop problem here with the BIG-IP server implementation. Thanks.

@martinduke
Copy link

Hello everyone, I'm in charge of F5's HTTP/2 code. We are aware of the problem and patched it in our upcoming release months ago. In a matter of days, this will also be available as a patch to deployed versions.

If this problem is affecting you, please contact F5 support and ask for the patch for bug number 677119.

@bradfitz
Copy link
Contributor

bradfitz commented Aug 9, 2017

@tombergan, what do you think of changing Go's http Transport to retry Requests with HTTP/1.1 if it sees a GOAWAY with LastStreamID=0?

@tombergan
Copy link
Contributor

@tombergan, what do you think of changing Go's http Transport to retry Requests with HTTP/1.1 if it sees a GOAWAY with LastStreamID=0?

We could do that but it would be somewhat complex: The H2 transport needs to return errGoAwayBeforeAnyRequests if it sees GOAWAY with LastStreamID=0. Then pconn.shouldRetryRequest needs to recognize this error. So far not too bad.

if !pconn.shouldRetryRequest(req, err) {

When that error happens (and only that error), we need to disable TLSNextProto on the next call to Transport.getConn and Transport.dialConn. Currently there's no easy way to do this, and adding such plumbing could get ugly. IMO, I'd rather wait until we had a second case where we could use this feature before adding it.

The current issue can be avoided by having the client set http2.Transport.MaxHeaderListSize to 32768 or lower. That seems like a better short-term fix while clients wait for the next F5 release to roll out.

@bradfitz bradfitz modified the milestones: Go1.10, Go1.11 Nov 29, 2017
@bradfitz bradfitz changed the title x/net/http2: connecting to some HTTP2 server returns Client.Timeout exceeded x/net/http2: connecting to non-compliant HTTP2 server returns Client.Timeout exceeded; fallback to HTTP/1? Nov 29, 2017
@bradfitz bradfitz modified the milestones: Go1.11, Unplanned Jul 9, 2018
@bradfitz bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Jul 9, 2018
@gopherbot gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 9, 2018
@HaraldNordgren
Copy link
Member

I'm not sure this ticket is the correct place to post this. I found this ticket from #21301 which seemed like a better description of my situation, but it was closed as a duplicate so now I'm posting here.

I was interacting with a TLS host where curl works, but from Golang it was hanging on requests. Interestingly enough, for malformed requests the host would return quickly with an error. But for the data that turned out to be correct, it was timing out.

I tried changing the HTTP version with no result. The solution that ended up working was to use DynamicRecordSizingDisabled in a config like this

...

tls.Config{
	Certificates:                []tls.Certificate{cert},
	Renegotiation:               tls.RenegotiateOnceAsClient,
	DynamicRecordSizingDisabled: true,
}

Again, Curl handles this seamlessly. So assuming there is a way to detect hosts that require DynamicRecordSizingDisabled, then it would be nice if Golang in the future could do this.

@bradfitz
Copy link
Contributor

@HaraldNordgren, please file a separate crypto/tls bug for your case. It's unrelated to this. It sounds like a TLS issue instead of an HTTP issue.

@keything
Copy link

keything commented Nov 14, 2018

I'm not sure this ticket is the correct place to post this. I found this ticket from #21301 which seemed like a better description of my situation, but it was closed as a duplicate so now I'm posting here.

I was interacting with a TLS host where curl works, but from Golang it was hanging on requests. Interestingly enough, for malformed requests the host would return quickly with an error. But for the data that turned out to be correct, it was timing out.

I tried changing the HTTP version with no result. The solution that ended up working was to use DynamicRecordSizingDisabled in a config like this

...

tls.Config{
	Certificates:                []tls.Certificate{cert},
	Renegotiation:               tls.RenegotiateOnceAsClient,
	DynamicRecordSizingDisabled: true,
}

Again, Curl handles this seamlessly. So assuming there is a way to detect hosts that require DynamicRecordSizingDisabled, then it would be nice if Golang in the future could do this.

hello, our client is as follows: `
timeout := time.Duration(999) * time.Millisecond

	rs.HttpClient = &http.Client{

		Transport: &http.Transport{

			MaxIdleConnsPerHost: 10000,

		},

		Timeout: timeout,
	}`, 

however, when we visit google with host maps.googleapis.com, timeout sometimes does not work。
The error we record is net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers) and net/http: request canceled (Client.Timeout exceeded while awaiting headers).
The latency is bigger than 100 second.

My question is that:

  1. your client is http.Client?
  2. what is your error message when it hangs

@keything
Copy link

I'm not sure this ticket is the correct place to post this. I found this ticket from #21301 which seemed like a better description of my situation, but it was closed as a duplicate so now I'm posting here.

I was interacting with a TLS host where curl works, but from Golang it was hanging on requests. Interestingly enough, for malformed requests the host would return quickly with an error. But for the data that turned out to be correct, it was timing out.

I tried changing the HTTP version with no result. The solution that ended up working was to use DynamicRecordSizingDisabled in a config like this

...

tls.Config{
	Certificates:                []tls.Certificate{cert},
	Renegotiation:               tls.RenegotiateOnceAsClient,
	DynamicRecordSizingDisabled: true,
}

Again, Curl handles this seamlessly. So assuming there is a way to detect hosts that require DynamicRecordSizingDisabled, then it would be nice if Golang in the future could do this.

`tls.Config {

DynamicRecordSizingDisabled: true,

}`

it works. however, i don't know why it works.

when DynamicRecordSizingDisabled is true, we disables adaptive sizing of TLS records.

Does it depend on the implementation of tls in server side?

@Gambler13
Copy link

Gambler13 commented Jun 5, 2019

Any news on this issue? Because I encountered the same problem. I try to make a simple GET request. In the browser (Chrome), command line (cURL) and ozher tools like Postman the request is working fine. But if I try to do the request with the http.Client, nothing happens and the request will timeout.

GO env

set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\fiss\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\Dev\Go
set GOPROXY=
set GORACE=
set GOROOT=C:\Go
set GOTMPDIR=
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Dev\Go\hexhibit\test-ssl\go.mod
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\fiss\AppData\Local\Temp\go-build889517290=/tmp/go-build -gno-record-gcc-switches

Sample Programm code

func main() {

	fmt.Println("-- start --")

	tr := &http.Transport{
//Due self signed certs
		TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
	}

	client := &http.Client{Transport: tr,
		Timeout: 15 * time.Second,
	}

	req, err := http.NewRequest("GET", "https://hidden-url.cc:8084/rest2/SecUserMethods/method/Authenticate?Name=ss&Password=ss", nil)
	if err != nil {
		panic(err)
	}

	fmt.Println("do request")
	resp, err := client.Do(req)
	if err != nil {
		panic(err)
	}
	defer resp.Body.Close()

	fmt.Println("request successfully")

	data, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		panic(err)
	}

	fmt.Printf("Data: %s", string(data))

}

Output
et/http: request canceled (Client.Timeout exceeded while awaiting headers)

Unfortunately, I can't provide the real URL (and in addition, a whitelisting is needed to call the url)
I already followed all the suggestions in this and other threads, but no one was working. And I also tried with golang 1.11.x, but ended with the same result.

Here the curl output (ignore the 404, this is intended)

https://hidden-url.cc:8084/rest2/SecUserMethods/method/Authenticate?Name=ss&Password=ss

* TCP_NODELAY set
* Connected to hidden-url (1.2.3.4) port 8084 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / DHE-RSA-AES256-SHA
* ALPN, server did not agree to a protocol
* Server certificate:
*  subject: CN=*.richemont.cc
*  start date: Jan 22 00:00:00 2018 GMT
*  expire date: Feb 21 12:00:00 2020 GMT
*  issuer: C=US; O=DigiCert Inc; OU=www.digicert.com; CN=RapidSSL RSA CA 2018
*  SSL certificate verify ok.
> GET /rest2/SecUserMethods/method/Authenticate?ClientID=5577006791947779410 HTTP/1.1
> Host: hidden-url:8084
> User-Agent: curl/7.58.0
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Content-Type: application/json;charset=utf-8
< Content-Length: 108
< Access-Control-Allow-Credentials: True
< Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept
< Access-Control-Allow-Methods: *
< Access-Control-Allow-Origin: *
<
{
"resource": [{
"type": "message",
"code": "404 Not Found",
"message": "parameter missing: Name"
}]

mvallaly-rally added a commit to mvallaly-rally/aws-okta that referenced this issue Sep 29, 2020
Seems OKTA has a broken implementation of HTTP2?
There seem to be some quirks with they way golang handles HTTP2 requests (specifically when receiving GOAWAY frames) golang/go#20979, which result in the HTTP2 connection not terminating.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests