search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
122.97k stars 17.53k forks source link

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

Open tkng opened 7 years ago

tkng commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

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 commented 7 years ago

It works in Chrome, though.

What's the difference?

tkng commented 7 years ago

@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 commented 7 years ago

@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 commented 7 years ago

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

bradfitz commented 7 years ago

@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 commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

/cc @scottmitch @normanmaurer

bradfitz commented 7 years ago

Is there another Netty server directly facing the Internet?

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

tombergan commented 7 years ago

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 commented 7 years ago

@bradfitz, do you have any contacts at F5?

bradfitz commented 7 years ago

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 commented 7 years ago

in response to https://github.com/golang/go/issues/20979#issuecomment-314635357 ... Netty does not do any immediate allocation as a result of receiving SETTINGS_MAX_HEADER_LIST_SIZE and as referenced in https://github.com/golang/go/issues/20979#issuecomment-315370909 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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

@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. https://github.com/golang/go/blob/75ab6134fcea003803e25c9bad7f092be3eeb5c3/src/net/http/transport.go#L418

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.

HaraldNordgren commented 6 years ago

I'm not sure this ticket is the correct place to post this. I found this ticket from https://github.com/golang/go/issues/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 commented 6 years ago

@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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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"
}]