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

Jump to bottom

x/net/http2: Shutdown closes active HTTP/2 connections #39919

Closed
nwidger opened this issue Jun 29, 2020 · 3 comments
Closed

x/net/http2: Shutdown closes active HTTP/2 connections #39919

nwidger opened this issue Jun 29, 2020 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.

Comments

@nwidger
Copy link
Contributor

nwidger commented Jun 29, 2020

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

$ go version
go version devel +6f6d4046eb Sat Jun 27 13:31:34 2020 -0600 darwin/amd64

Built from https://golang.org/cl/240278 related to #36946 and #39776.

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/niels/Library/Caches/go-build"
GOENV="/Users/niels/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/niels/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/niels/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/niels/gosrc"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/niels/gosrc/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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/bb/xxdvfvm103n8p4vktz66d7d40000gn/T/go-build954639029=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Calling Shutdown inside the response handler for request 4 of an HTTP/2 connection causes the server to shutdown before the response for request 4 is written:

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

Here is sample output with GODEBUG=http2debug=2:

GODEBUG=http2debug=2 go run main2.go Output
$ GODEBUG=http2debug=2 go run main2.go
2020/06/29 10:30:16 server: listening on 127.0.0.1:8443
2020/06/29 10:30:18 client: request 1: sent
2020/06/29 10:30:18 http2: Transport failed to get client conn for 127.0.0.1:8443: http2: no cached connection was available
2020/06/29 10:30:18 http1 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state new
2020/06/29 10:30:18 http2: Transport creating client conn 0xc000104f00 to 127.0.0.1:8443
2020/06/29 10:30:18 http2: server connection from 127.0.0.1:53302 on 0xc000284000
2020/06/29 10:30:18 http2: Framer 0xc000284460: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/29 10:30:18 http2: Framer 0xc000284460: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/29 10:30:18 http2: Framer 0xc00030a000: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/29 10:30:18 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:18 http2: Transport encoding header ":method" = "GET"
2020/06/29 10:30:18 http2: Transport encoding header ":path" = "/"
2020/06/29 10:30:18 http2: Transport encoding header ":scheme" = "https"
2020/06/29 10:30:18 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/29 10:30:18 http2: server: client 127.0.0.1:53302 said hello
2020/06/29 10:30:18 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:18 http2: Framer 0xc000284460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/29 10:30:18 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state active
2020/06/29 10:30:18 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state idle
2020/06/29 10:30:18 http2: Framer 0xc00030a000: read SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/29 10:30:18 http2: Framer 0xc00030a000: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/29 10:30:18 http2: server read frame SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/29 10:30:18 http2: server processing setting [ENABLE_PUSH = 0]
2020/06/29 10:30:18 http2: server processing setting [INITIAL_WINDOW_SIZE = 4194304]
2020/06/29 10:30:18 http2: server processing setting [MAX_HEADER_LIST_SIZE = 10485760]
2020/06/29 10:30:18 http2: Framer 0xc000284460: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/29 10:30:18 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/29 10:30:18 http2: Framer 0xc00030a000: wrote SETTINGS flags=ACK len=0
2020/06/29 10:30:18 http2: Framer 0xc000284460: wrote SETTINGS flags=ACK len=0
2020/06/29 10:30:18 http2: Framer 0xc00030a000: read WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/29 10:30:18 http2: Framer 0xc000284460: read WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/29 10:30:18 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/29 10:30:18 http2: Framer 0xc000284460: read SETTINGS flags=ACK len=0
2020/06/29 10:30:18 http2: Transport received SETTINGS flags=ACK len=0
2020/06/29 10:30:18 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/29 10:30:18 http2: Framer 0xc00030a000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/29 10:30:18 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:18 http2: decoded hpack field header field ":method" = "GET"
2020/06/29 10:30:18 http2: decoded hpack field header field ":path" = "/"
2020/06/29 10:30:18 http2: decoded hpack field header field ":scheme" = "https"
2020/06/29 10:30:18 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/29 10:30:18 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:18 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/29 10:30:18 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state active
2020/06/29 10:30:18 http2: Framer 0xc00030a000: read SETTINGS flags=ACK len=0
2020/06/29 10:30:18 http2: server read frame SETTINGS flags=ACK len=0
2020/06/29 10:30:21 http2: server encoding header ":status" = "200"
2020/06/29 10:30:21 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:21 http2: server encoding header "content-length" = "30"
2020/06/29 10:30:21 http2: server encoding header "date" = "Mon, 29 Jun 2020 14:30:21 GMT"
2020/06/29 10:30:21 http2: Framer 0xc00030a000: wrote HEADERS flags=END_HEADERS stream=1 len=49
2020/06/29 10:30:21 http2: Framer 0xc00030a000: wrote DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/29 10:30:21 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state idle
2020/06/29 10:30:21 http2: Framer 0xc000284460: read HEADERS flags=END_HEADERS stream=1 len=49
2020/06/29 10:30:21 http2: decoded hpack field header field ":status" = "200"
2020/06/29 10:30:21 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:21 http2: decoded hpack field header field "content-length" = "30"
2020/06/29 10:30:21 http2: decoded hpack field header field "date" = "Mon, 29 Jun 2020 14:30:21 GMT"
2020/06/29 10:30:21 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=49
2020/06/29 10:30:21 http2: Framer 0xc000284460: read DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/29 10:30:21 http2: Transport received DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/29 10:30:21 client: request 1: response: 200: received request 1 over http2
2020/06/29 10:30:21 client: request 2: sent
2020/06/29 10:30:21 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:21 http2: Transport encoding header ":method" = "GET"
2020/06/29 10:30:21 http2: Transport encoding header ":path" = "/"
2020/06/29 10:30:21 http2: Transport encoding header ":scheme" = "https"
2020/06/29 10:30:21 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/29 10:30:21 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:21 http2: Framer 0xc000284460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/29 10:30:21 http2: Framer 0xc00030a000: read HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/29 10:30:21 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:21 http2: decoded hpack field header field ":method" = "GET"
2020/06/29 10:30:21 http2: decoded hpack field header field ":path" = "/"
2020/06/29 10:30:21 http2: decoded hpack field header field ":scheme" = "https"
2020/06/29 10:30:21 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/29 10:30:21 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:21 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/29 10:30:21 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state active
2020/06/29 10:30:24 http2: server encoding header ":status" = "200"
2020/06/29 10:30:24 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:24 http2: server encoding header "content-length" = "30"
2020/06/29 10:30:24 http2: server encoding header "date" = "Mon, 29 Jun 2020 14:30:24 GMT"
2020/06/29 10:30:24 http2: Framer 0xc00030a000: wrote HEADERS flags=END_HEADERS stream=3 len=27
2020/06/29 10:30:24 http2: Framer 0xc00030a000: wrote DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/29 10:30:24 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state idle
2020/06/29 10:30:24 http2: Framer 0xc000284460: read HEADERS flags=END_HEADERS stream=3 len=27
2020/06/29 10:30:24 http2: decoded hpack field header field ":status" = "200"
2020/06/29 10:30:24 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:24 http2: decoded hpack field header field "content-length" = "30"
2020/06/29 10:30:24 http2: decoded hpack field header field "date" = "Mon, 29 Jun 2020 14:30:24 GMT"
2020/06/29 10:30:24 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=27
2020/06/29 10:30:24 http2: Framer 0xc000284460: read DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/29 10:30:24 http2: Transport received DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/29 10:30:24 client: request 2: response: 200: received request 2 over http2
2020/06/29 10:30:24 client: request 3: sent
2020/06/29 10:30:24 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:24 http2: Transport encoding header ":method" = "GET"
2020/06/29 10:30:24 http2: Transport encoding header ":path" = "/"
2020/06/29 10:30:24 http2: Transport encoding header ":scheme" = "https"
2020/06/29 10:30:24 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/29 10:30:24 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:24 http2: Framer 0xc000284460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/29 10:30:24 http2: Framer 0xc00030a000: read HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/29 10:30:24 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:24 http2: decoded hpack field header field ":method" = "GET"
2020/06/29 10:30:24 http2: decoded hpack field header field ":path" = "/"
2020/06/29 10:30:24 http2: decoded hpack field header field ":scheme" = "https"
2020/06/29 10:30:24 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/29 10:30:24 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:24 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/29 10:30:24 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state active
2020/06/29 10:30:27 http2: server encoding header ":status" = "200"
2020/06/29 10:30:27 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:27 http2: server encoding header "content-length" = "30"
2020/06/29 10:30:27 http2: server encoding header "date" = "Mon, 29 Jun 2020 14:30:27 GMT"
2020/06/29 10:30:27 http2: Framer 0xc00030a000: wrote HEADERS flags=END_HEADERS stream=5 len=27
2020/06/29 10:30:27 http2: Framer 0xc00030a000: wrote DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/29 10:30:27 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state idle
2020/06/29 10:30:27 http2: Framer 0xc000284460: read HEADERS flags=END_HEADERS stream=5 len=27
2020/06/29 10:30:27 http2: decoded hpack field header field ":status" = "200"
2020/06/29 10:30:27 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/29 10:30:27 http2: decoded hpack field header field "content-length" = "30"
2020/06/29 10:30:27 http2: decoded hpack field header field "date" = "Mon, 29 Jun 2020 14:30:27 GMT"
2020/06/29 10:30:27 http2: Transport received HEADERS flags=END_HEADERS stream=5 len=27
2020/06/29 10:30:27 http2: Framer 0xc000284460: read DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/29 10:30:27 http2: Transport received DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/29 10:30:27 client: request 3: response: 200: received request 3 over http2
2020/06/29 10:30:27 client: request 4: sent
2020/06/29 10:30:27 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:27 http2: Transport encoding header ":method" = "GET"
2020/06/29 10:30:27 http2: Transport encoding header ":path" = "/"
2020/06/29 10:30:27 http2: Transport encoding header ":scheme" = "https"
2020/06/29 10:30:27 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/29 10:30:27 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:27 http2: Framer 0xc000284460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/29 10:30:27 http2: Framer 0xc00030a000: read HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/29 10:30:27 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/29 10:30:27 http2: decoded hpack field header field ":method" = "GET"
2020/06/29 10:30:27 http2: decoded hpack field header field ":path" = "/"
2020/06/29 10:30:27 http2: decoded hpack field header field ":scheme" = "https"
2020/06/29 10:30:27 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/29 10:30:27 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/29 10:30:27 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/29 10:30:27 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:53302: state active
2020/06/29 10:30:27 ========== calling shutdown ==========
2020/06/29 10:30:27 servertls error: http: Server closed
2020/06/29 10:30:27 server: no longer serving, waiting 5s seconds before exiting...
2020/06/29 10:30:27 http2: Framer 0xc00030a000: wrote GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/29 10:30:27 http2: Framer 0xc000284460: read GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/29 10:30:27 http2: Transport received GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/29 10:30:32 done.

What did you expect to see?

The server should wait until the response for request 4 is written before closing down the server.

What did you see instead?

The server is shutdown before the response is written.

/cc @fraenkel
@nwidger nwidger mentioned this issue Jun 29, 2020
Closed
@fraenkel
Copy link
Contributor

There is an issue with your test. Shutdown() is synchronous.
The listeners are closed as the very first step so your 5s count down will always exit.
If you do a thread dump, you will see the handler still waiting to Shutdown(). It obviously cannot since its the active connection that its awaiting.

@nwidger
Copy link
Contributor Author

nwidger commented Jun 30, 2020

@fraenkel You're absolutely right, that indeed explains the behavior. I should have given the recipe I wrote back in January a closer look before opening this issue with it, I apologize for that. I've confirmed that by launching Shutdown() in a separate goroutine from within the handler, things appear to be working correctly:

https://play.golang.org/p/4GnoUQ2Ld7N

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/niels/Library/Caches/go-build"
GOENV="/Users/niels/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/niels/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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/bb/xxdvfvm103n8p4vktz66d7d40000gn/T/go-build782134848=/tmp/go-build -gno-record-gcc-switches -fno-common"
GODEBUG=http2debug=2 bin/go run main2.go Output
$ GODEBUG=http2debug=2 bin/go run main2.go
2020/06/30 08:17:28 server: listening on 127.0.0.1:8443
2020/06/30 08:17:30 client: request 1: sent
2020/06/30 08:17:30 http2: Transport failed to get client conn for 127.0.0.1:8443: http2: no cached connection was available
2020/06/30 08:17:30 http1 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state new
2020/06/30 08:17:30 http2: Transport creating client conn 0xc00025c300 to 127.0.0.1:8443
2020/06/30 08:17:30 http2: Framer 0xc000248460: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/30 08:17:30 http2: Framer 0xc000248460: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/30 08:17:30 http2: server connection from 127.0.0.1:57422 on 0xc000248000
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/30 08:17:30 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:30 http2: Transport encoding header ":method" = "GET"
2020/06/30 08:17:30 http2: Transport encoding header ":path" = "/"
2020/06/30 08:17:30 http2: Transport encoding header ":scheme" = "https"
2020/06/30 08:17:30 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/30 08:17:30 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:30 http2: Framer 0xc000248460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/30 08:17:30 http2: server: client 127.0.0.1:57422 said hello
2020/06/30 08:17:30 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state active
2020/06/30 08:17:30 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state idle
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: read SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/30 08:17:30 http2: server read frame SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/06/30 08:17:30 http2: server processing setting [ENABLE_PUSH = 0]
2020/06/30 08:17:30 http2: server processing setting [INITIAL_WINDOW_SIZE = 4194304]
2020/06/30 08:17:30 http2: Framer 0xc000248460: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/30 08:17:30 http2: server processing setting [MAX_HEADER_LIST_SIZE = 10485760]
2020/06/30 08:17:30 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2020/06/30 08:17:30 http2: Framer 0xc000248460: wrote SETTINGS flags=ACK len=0
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: wrote SETTINGS flags=ACK len=0
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: read WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/30 08:17:30 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/30 08:17:30 http2: Framer 0xc000248460: read SETTINGS flags=ACK len=0
2020/06/30 08:17:30 http2: Transport received SETTINGS flags=ACK len=0
2020/06/30 08:17:30 http2: Framer 0xc000248460: read WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/30 08:17:30 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2020/06/30 08:17:30 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:30 http2: decoded hpack field header field ":method" = "GET"
2020/06/30 08:17:30 http2: decoded hpack field header field ":path" = "/"
2020/06/30 08:17:30 http2: decoded hpack field header field ":scheme" = "https"
2020/06/30 08:17:30 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/30 08:17:30 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:30 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35
2020/06/30 08:17:30 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state active
2020/06/30 08:17:30 http2: Framer 0xc0000ca000: read SETTINGS flags=ACK len=0
2020/06/30 08:17:30 http2: server read frame SETTINGS flags=ACK len=0
2020/06/30 08:17:33 http2: server encoding header ":status" = "200"
2020/06/30 08:17:33 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:33 http2: server encoding header "content-length" = "30"
2020/06/30 08:17:33 http2: server encoding header "date" = "Tue, 30 Jun 2020 12:17:33 GMT"
2020/06/30 08:17:33 http2: Framer 0xc0000ca000: wrote HEADERS flags=END_HEADERS stream=1 len=49
2020/06/30 08:17:33 http2: Framer 0xc0000ca000: wrote DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/30 08:17:33 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state idle
2020/06/30 08:17:33 http2: Framer 0xc000248460: read HEADERS flags=END_HEADERS stream=1 len=49
2020/06/30 08:17:33 http2: decoded hpack field header field ":status" = "200"
2020/06/30 08:17:33 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:33 http2: decoded hpack field header field "content-length" = "30"
2020/06/30 08:17:33 http2: decoded hpack field header field "date" = "Tue, 30 Jun 2020 12:17:33 GMT"
2020/06/30 08:17:33 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=49
2020/06/30 08:17:33 http2: Framer 0xc000248460: read DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/30 08:17:33 http2: Transport received DATA flags=END_STREAM stream=1 len=30 data="received request 1 over http2\n"
2020/06/30 08:17:33 client: request 1: response: 200: received request 1 over http2
2020/06/30 08:17:33 client: request 2: sent
2020/06/30 08:17:33 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:33 http2: Transport encoding header ":method" = "GET"
2020/06/30 08:17:33 http2: Transport encoding header ":path" = "/"
2020/06/30 08:17:33 http2: Transport encoding header ":scheme" = "https"
2020/06/30 08:17:33 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/30 08:17:33 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:33 http2: Framer 0xc000248460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/30 08:17:33 http2: Framer 0xc0000ca000: read HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/30 08:17:33 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:33 http2: decoded hpack field header field ":method" = "GET"
2020/06/30 08:17:33 http2: decoded hpack field header field ":path" = "/"
2020/06/30 08:17:33 http2: decoded hpack field header field ":scheme" = "https"
2020/06/30 08:17:33 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/30 08:17:33 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:33 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=3 len=6
2020/06/30 08:17:33 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state active
2020/06/30 08:17:36 http2: server encoding header ":status" = "200"
2020/06/30 08:17:36 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:36 http2: server encoding header "content-length" = "30"
2020/06/30 08:17:36 http2: server encoding header "date" = "Tue, 30 Jun 2020 12:17:36 GMT"
2020/06/30 08:17:36 http2: Framer 0xc0000ca000: wrote HEADERS flags=END_HEADERS stream=3 len=27
2020/06/30 08:17:36 http2: Framer 0xc0000ca000: wrote DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/30 08:17:36 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state idle
2020/06/30 08:17:36 http2: Framer 0xc000248460: read HEADERS flags=END_HEADERS stream=3 len=27
2020/06/30 08:17:36 http2: decoded hpack field header field ":status" = "200"
2020/06/30 08:17:36 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:36 http2: decoded hpack field header field "content-length" = "30"
2020/06/30 08:17:36 http2: decoded hpack field header field "date" = "Tue, 30 Jun 2020 12:17:36 GMT"
2020/06/30 08:17:36 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=27
2020/06/30 08:17:36 http2: Framer 0xc000248460: read DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/30 08:17:36 http2: Transport received DATA flags=END_STREAM stream=3 len=30 data="received request 2 over http2\n"
2020/06/30 08:17:36 client: request 2: response: 200: received request 2 over http2
2020/06/30 08:17:36 client: request 3: sent
2020/06/30 08:17:36 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:36 http2: Transport encoding header ":method" = "GET"
2020/06/30 08:17:36 http2: Transport encoding header ":path" = "/"
2020/06/30 08:17:36 http2: Transport encoding header ":scheme" = "https"
2020/06/30 08:17:36 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/30 08:17:36 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:36 http2: Framer 0xc000248460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/30 08:17:36 http2: Framer 0xc0000ca000: read HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/30 08:17:36 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:36 http2: decoded hpack field header field ":method" = "GET"
2020/06/30 08:17:36 http2: decoded hpack field header field ":path" = "/"
2020/06/30 08:17:36 http2: decoded hpack field header field ":scheme" = "https"
2020/06/30 08:17:36 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/30 08:17:36 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:36 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=5 len=6
2020/06/30 08:17:36 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state active
2020/06/30 08:17:39 http2: server encoding header ":status" = "200"
2020/06/30 08:17:39 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:39 http2: server encoding header "content-length" = "30"
2020/06/30 08:17:39 http2: server encoding header "date" = "Tue, 30 Jun 2020 12:17:39 GMT"
2020/06/30 08:17:39 http2: Framer 0xc0000ca000: wrote HEADERS flags=END_HEADERS stream=5 len=27
2020/06/30 08:17:39 http2: Framer 0xc0000ca000: wrote DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/30 08:17:39 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state idle
2020/06/30 08:17:39 http2: Framer 0xc000248460: read HEADERS flags=END_HEADERS stream=5 len=27
2020/06/30 08:17:39 http2: decoded hpack field header field ":status" = "200"
2020/06/30 08:17:39 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:39 http2: decoded hpack field header field "content-length" = "30"
2020/06/30 08:17:39 http2: decoded hpack field header field "date" = "Tue, 30 Jun 2020 12:17:39 GMT"
2020/06/30 08:17:39 http2: Transport received HEADERS flags=END_HEADERS stream=5 len=27
2020/06/30 08:17:39 http2: Framer 0xc000248460: read DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/30 08:17:39 http2: Transport received DATA flags=END_STREAM stream=5 len=30 data="received request 3 over http2\n"
2020/06/30 08:17:39 client: request 3: response: 200: received request 3 over http2
2020/06/30 08:17:39 client: request 4: sent
2020/06/30 08:17:39 http2: Transport encoding header ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:39 http2: Transport encoding header ":method" = "GET"
2020/06/30 08:17:39 http2: Transport encoding header ":path" = "/"
2020/06/30 08:17:39 http2: Transport encoding header ":scheme" = "https"
2020/06/30 08:17:39 http2: Transport encoding header "accept-encoding" = "gzip"
2020/06/30 08:17:39 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:39 http2: Framer 0xc000248460: wrote HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/30 08:17:39 http2: Framer 0xc0000ca000: read HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/30 08:17:39 http2: decoded hpack field header field ":authority" = "127.0.0.1:8443"
2020/06/30 08:17:39 http2: decoded hpack field header field ":method" = "GET"
2020/06/30 08:17:39 http2: decoded hpack field header field ":path" = "/"
2020/06/30 08:17:39 http2: decoded hpack field header field ":scheme" = "https"
2020/06/30 08:17:39 http2: decoded hpack field header field "accept-encoding" = "gzip"
2020/06/30 08:17:39 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2020/06/30 08:17:39 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=7 len=6
2020/06/30 08:17:39 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state active
2020/06/30 08:17:39 ========== calling shutdown ==========
2020/06/30 08:17:39 servertls error: http: Server closed
2020/06/30 08:17:39 server: no longer serving, waiting 5s seconds before exiting...
2020/06/30 08:17:39 http2: Framer 0xc0000ca000: wrote GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/30 08:17:39 http2: Framer 0xc000248460: read GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/30 08:17:39 http2: Transport received GOAWAY len=8 LastStreamID=7 ErrCode=NO_ERROR Debug=""
2020/06/30 08:17:42 http2: server encoding header ":status" = "200"
2020/06/30 08:17:42 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:42 http2: server encoding header "content-length" = "30"
2020/06/30 08:17:42 http2: server encoding header "date" = "Tue, 30 Jun 2020 12:17:42 GMT"
2020/06/30 08:17:42 http2: Framer 0xc0000ca000: wrote HEADERS flags=END_HEADERS stream=7 len=27
2020/06/30 08:17:42 http2: Framer 0xc0000ca000: wrote DATA flags=END_STREAM stream=7 len=30 data="received request 4 over http2\n"
2020/06/30 08:17:42 http2 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state idle
2020/06/30 08:17:42 http2: Framer 0xc000248460: read HEADERS flags=END_HEADERS stream=7 len=27
2020/06/30 08:17:42 http2: decoded hpack field header field ":status" = "200"
2020/06/30 08:17:42 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2020/06/30 08:17:42 http2: decoded hpack field header field "content-length" = "30"
2020/06/30 08:17:42 http2: decoded hpack field header field "date" = "Tue, 30 Jun 2020 12:17:42 GMT"
2020/06/30 08:17:42 http2: Transport received HEADERS flags=END_HEADERS stream=7 len=27
2020/06/30 08:17:42 http2: Framer 0xc000248460: read DATA flags=END_STREAM stream=7 len=30 data="received request 4 over http2\n"
2020/06/30 08:17:42 http2: Transport received DATA flags=END_STREAM stream=7 len=30 data="received request 4 over http2\n"
2020/06/30 08:17:42 client: request 4: response: 200: received request 4 over http2
2020/06/30 08:17:42 client: request 5: sent
2020/06/30 08:17:42 http2: Transport failed to get client conn for 127.0.0.1:8443: http2: no cached connection was available
2020/06/30 08:17:42 http2: Transport failed to get client conn for 127.0.0.1:8443: http2: no cached connection was available
2020/06/30 08:17:42 client: request 5: error: Get "https://127.0.0.1:8443/": dial tcp 127.0.0.1:8443: connect: connection refused
2020/06/30 08:17:43 GOAWAY close timer fired; closing conn from 127.0.0.1:57422
2020/06/30 08:17:43 http2: Transport readFrame error on conn 0xc00025c300: (*errors.errorString) EOF
2020/06/30 08:17:43 http1 connstate: 127.0.0.1:8443 -> 127.0.0.1:57422: state closed
2020/06/30 08:17:44 ==========  called shutdown ==========
2020/06/30 08:17:44 done.

If you agree that the behavior looks good, I suppose we should close this issue. Thanks again for taking the time to look into this.

@fraenkel
Copy link
Contributor

That looks right. We should close this.

@nwidger nwidger closed this as completed Jun 30, 2020
@dmitshur dmitshur added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 1, 2020
@golang golang locked and limited conversation to collaborators Sep 1, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@nwidger @fraenkel @dmitshur @gopherbot