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: PROTOCOL_ERROR after GOAWAY #32112

Open
mightyguava opened this issue May 17, 2019 · 9 comments

Comments

@mightyguava
Copy link

commented May 17, 2019

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

$ go version
go version go1.12.4 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

This reproduces on Linux as well. I've been grabbing debugging data from my mac though.

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/yunchiluo/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/yunchiluo/Development/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.12.4/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.12.4/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
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/cc/twp3z6t52hvcp1hsxkmws_rm0000gn/T/go-build356526983=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

We are running http2 servers behind a TCP ELB loadbalancer (we need to terminate SSL at the server). This is causing unbalanced traffic since clients try to multiplex a single http2 connection. We had the idea of randomly sending GOAWAY to get clients to close their connections.

// CycleConnections sends a GOAWAY frame with a given probability after the request completes.
func CycleConnections(probability float64, next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		if r.ProtoMajor == 2 && rand.Float64() < probability {
			// The "Connection: close" header is turned into a GOAWAY frame by the http2 server.
			w.Header().Add("Connection", "close")
			log.Info("cycling http2 connection")
		}
		next.ServeHTTP(w, r)
	})
}

I then ran fake traffic using Vegeta to my server. So Go client/server.

What did you expect to see?

I expect that when a GOAWAY frame is sent, the server will complete processing of any open requests, and the client will open a new connection for new requests. This should all be transparent to user code. (I expected maybe I'd see http.Client return some errors about GOAWAY, but haven't seen that)

What did you see instead?

The connection close chance was set at 0.5. At low qps, <10, everything is fine, no errors. Ramping up qps to 50, I start seeing PROTOCOL_ERROR coming from the server. This is reproducible locally with no load balancer in between client/server.

Here's server and client logs for such occurrence:

Server logs

2019-05-17T12:44:52.115009-04:00 cycling http2 connection 
2019-05-17T12:44:52.115013-04:00 http2: Framer 0xc000238460: read SETTINGS flags=ACK len=0
2019-05-17T12:44:52.115024-04:00 http2: server read frame SETTINGS flags=ACK len=0 
2019-05-17T12:44:52.115093-04:00 http2: Framer 0xc000238460: read DATA stream=1 len=258 data="redacted"
2019-05-17T12:44:52.115147-04:00 http2: Framer 0xc000238460: read DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.115149-04:00 http2: server read frame DATA stream=1 len=258 data="redacted"
2019-05-17T12:44:52.11517-04:00 http2: Framer 0xc000238460: wrote WINDOW_UPDATE len=4 (conn) incr=258
2019-05-17T12:44:52.115205-04:00 http2: server read frame DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.115227-04:00 http2: Framer 0xc000238460: wrote WINDOW_UPDATE stream=1 len=4 incr=258
2019-05-17T12:44:52.118329-04:00 http2: Framer 0xc000238460: wrote GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=\"\"
2019-05-17T12:44:52.11837-04:00 http2: Framer 0xc000238460: read HEADERS flags=END_HEADERS stream=3 len=8
2019-05-17T12:44:52.118409-04:00 http2: decoded hpack field header field \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.118433-04:00 http2: decoded hpack field header field \":method\" = \"POST\"
2019-05-17T12:44:52.118464-04:00 http2: decoded hpack field header field \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.118503-04:00 http2: server encoding header \":status\" = \"200\"
2019-05-17T12:44:52.118526-04:00 http2: server encoding header \"content-type\" = \"application/json\"
2019-05-17T12:44:52.118564-04:00 http2: server encoding header \"content-length\" = \"224\"
2019-05-17T12:44:52.118592-04:00 http2: decoded hpack field header field \":scheme\" = \"https\"
2019-05-17T12:44:52.118615-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.118637-04:00 http2: decoded hpack field header field \"content-length\" = \"258\"
2019-05-17T12:44:52.118663-04:00 http2: decoded hpack field header field \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.118691-04:00 http2: decoded hpack field header field \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.118741-04:00 http2: server read frame HEADERS flags=END_HEADERS stream=3 len=8 
2019-05-17T12:44:52.118743-04:00 http2: server encoding header \"date\" = \"Fri, 17 May 2019 16:44:52 GMT\"
2019-05-17T12:44:52.1188-04:00 http2: Framer 0xc000238460: wrote HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.118831-04:00 http2: Framer 0xc000238460: read DATA stream=3 len=258 data="redacted"
2019-05-17T12:44:52.118856-04:00 http2: server read frame DATA stream=3 len=258 data="redacted"
2019-05-17T12:44:52.118926-04:00 http2: server connection error from 127.0.0.1:51029: connection error: PROTOCOL_ERROR 
2019-05-17T12:44:52.118939-04:00 http2: Framer 0xc000238460: wrote DATA flags=END_STREAM stream=1 len=224 data="redacted"
2019-05-17T12:44:52.11898-04:00 http2: Framer 0xc000238460: read DATA flags=END_STREAM stream=3 len=0 data="redacted"
2019-05-17T12:44:52.118985-04:00 http2: server read frame DATA flags=END_STREAM stream=3 len=0 data="redacted"
2019-05-17T12:44:52.119036-04:00 http2: server connection error from 127.0.0.1:51029: connection error: PROTOCOL_ERROR 
2019-05-17T12:44:52.125133-04:00 http2: server connection from 127.0.0.1:51031 on 0xc000e00820 
2019-05-17T12:44:52.125193-04:00 http2: Framer 0xc000238b60: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019-05-17T12:44:52.125383-04:00 http2: server: client 127.0.0.1:51031 said hello 
2019-05-17T12:44:52.125422-04:00 http2: Framer 0xc000238b60: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2019-05-17T12:44:52.125466-04:00 http2: Framer 0xc000238b60: read SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019-05-17T12:44:52.125519-04:00 http2: server read frame SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760 
2019-05-17T12:44:52.125557-04:00 http2: server processing setting [ENABLE_PUSH = 0] 
2019-05-17T12:44:52.125586-04:00 http2: server processing setting [INITIAL_WINDOW_SIZE = 4194304] 
2019-05-17T12:44:52.125612-04:00 http2: Framer 0xc000238b60: wrote SETTINGS flags=ACK len=0
2019-05-17T12:44:52.125631-04:00 http2: server processing setting [MAX_HEADER_LIST_SIZE = 10485760] 
2019-05-17T12:44:52.125646-04:00 http2: Framer 0xc000238b60: read WINDOW_UPDATE len=4 (conn) incr=1073741824
2019-05-17T12:44:52.125662-04:00 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=1073741824 
2019-05-17T12:44:52.125779-04:00 http2: Framer 0xc000238b60: read HEADERS flags=END_HEADERS stream=1 len=78
2019-05-17T12:44:52.125862-04:00 http2: decoded hpack field header field \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.125895-04:00 http2: decoded hpack field header field \":method\" = \"POST\"
2019-05-17T12:44:52.125939-04:00 http2: decoded hpack field header field \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.125992-04:00 http2: decoded hpack field header field \":scheme\" = \"https\"
2019-05-17T12:44:52.126016-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.126035-04:00 http2: decoded hpack field header field \"content-length\" = \"258\"
2019-05-17T12:44:52.126049-04:00 http2: decoded hpack field header field \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.126064-04:00 http2: decoded hpack field header field \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.126068-04:00 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=78 
2019-05-17T12:44:52.126126-04:00 http2: Framer 0xc000238b60: read SETTINGS flags=ACK len=0
2019-05-17T12:44:52.12616-04:00 http2: server read frame SETTINGS flags=ACK len=0 
2019-05-17T12:44:52.126183-04:00 http2: Framer 0xc000238b60: read DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.12622-04:00 http2: server read frame DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.126336-04:00 Request failed elapsed="171.371µs" 
2019-05-17T12:44:52.126394-04:00 http2: server encoding header \":status\" = \"400\"
2019-05-17T12:44:52.126429-04:00 http2: server encoding header \"content-type\" = \"application/json\"
2019-05-17T12:44:52.126466-04:00 http2: server encoding header \"content-length\" = \"86\"
2019-05-17T12:44:52.126505-04:00 http2: server encoding header \"date\" = \"Fri, 17 May 2019 16:44:52 GMT\"
2019-05-17T12:44:52.126533-04:00 http2: Framer 0xc000238b60: wrote HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.126608-04:00 http2: Framer 0xc000238b60: wrote DATA flags=END_STREAM stream=1 len=86 data="redacted"
2019-05-17T12:44:52.12689-04:00 http2: Framer 0xc000238b60: read HEADERS flags=END_HEADERS stream=3 len=8
2019-05-17T12:44:52.126926-04:00 http2: decoded hpack field header field \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.126963-04:00 http2: decoded hpack field header field \":method\" = \"POST\"
2019-05-17T12:44:52.126986-04:00 http2: decoded hpack field header field \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.127016-04:00 http2: decoded hpack field header field \":scheme\" = \"https\"
2019-05-17T12:44:52.127031-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.127045-04:00 http2: decoded hpack field header field \"content-length\" = \"258\"
2019-05-17T12:44:52.127061-04:00 http2: decoded hpack field header field \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.1271-04:00 http2: server read frame HEADERS flags=END_HEADERS stream=3 len=8 
2019-05-17T12:44:52.127126-04:00 http2: decoded hpack field header field \"user-agent\" = \"Go-http-client/2.0\"

Client logs:

2019-05-17T12:44:52.106537-04:00 http2: Transport failed to get client conn for localhost:8443: http2: no cached connection was available
2019-05-17T12:44:52.114077-04:00 http2: Transport creating client conn 0xc0003e6900 to 127.0.0.1:8443
2019-05-17T12:44:52.114147-04:00 http2: Framer 0xc000272700: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019-05-17T12:44:52.114176-04:00 http2: Framer 0xc000272700: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019-05-17T12:44:52.114241-04:00 http2: Transport encoding header \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.11427-04:00 http2: Framer 0xc000272700: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019-05-17T12:44:52.114318-04:00 http2: Transport encoding header \":method\" = \"POST\"
2019-05-17T12:44:52.114342-04:00 http2: Transport encoding header \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.11437-04:00 http2: Transport encoding header \":scheme\" = \"https\"
2019-05-17T12:44:52.114404-04:00 http2: Transport encoding header \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.114434-04:00 http2: Transport encoding header \"content-length\" = \"258\"
2019-05-17T12:44:52.114455-04:00 http2: Transport encoding header \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.114498-04:00 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019-05-17T12:44:52.114542-04:00 http2: Transport encoding header \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.114577-04:00 http2: Framer 0xc000272700: wrote HEADERS flags=END_HEADERS stream=1 len=78
2019-05-17T12:44:52.11461-04:00 http2: Framer 0xc000272700: wrote SETTINGS flags=ACK len=0
2019-05-17T12:44:52.114669-04:00 http2: Framer 0xc000272700: read WINDOW_UPDATE len=4 (conn) incr=983041
2019-05-17T12:44:52.114704-04:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2019-05-17T12:44:52.114733-04:00 http2: Framer 0xc000272700: read SETTINGS flags=ACK len=0
2019-05-17T12:44:52.114763-04:00 http2: Transport received SETTINGS flags=ACK len=0
2019-05-17T12:44:52.11481-04:00 http2: Framer 0xc000272700: wrote DATA stream=1 len=258 data="redacted"
2019-05-17T12:44:52.114864-04:00 http2: Framer 0xc000272700: wrote DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.11527-04:00 http2: Framer 0xc000272700: read WINDOW_UPDATE len=4 (conn) incr=258
2019-05-17T12:44:52.115307-04:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=258
2019-05-17T12:44:52.115345-04:00 http2: Framer 0xc000272700: read WINDOW_UPDATE stream=1 len=4 incr=258
2019-05-17T12:44:52.11537-04:00 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=258
2019-05-17T12:44:52.11802-04:00 http2: Transport encoding header \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.118053-04:00 http2: Transport encoding header \":method\" = \"POST\"
2019-05-17T12:44:52.118087-04:00 http2: Transport encoding header \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.118112-04:00 http2: Transport encoding header \":scheme\" = \"https\"
2019-05-17T12:44:52.118141-04:00 http2: Transport encoding header \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.11816-04:00 http2: Transport encoding header \"content-length\" = \"258\"
2019-05-17T12:44:52.118192-04:00 http2: Transport encoding header \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.118218-04:00 http2: Transport encoding header \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.118253-04:00 http2: Framer 0xc000272700: wrote HEADERS flags=END_HEADERS stream=3 len=8
2019-05-17T12:44:52.118371-04:00 http2: Framer 0xc000272700: wrote DATA stream=3 len=258 data="redacted"
2019-05-17T12:44:52.118425-04:00 http2: Framer 0xc000272700: read GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=\"\"
2019-05-17T12:44:52.118456-04:00 http2: Transport received GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=\"\"
2019-05-17T12:44:52.118504-04:00 http2: Framer 0xc000272700: wrote DATA flags=END_STREAM stream=3 len=0 data="redacted"
2019-05-17T12:44:52.118533-04:00 http2: Transport failed to get client conn for localhost:8443: http2: no cached connection was available
2019-05-17T12:44:52.118862-04:00 http2: Framer 0xc000272700: read HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.118913-04:00 http2: decoded hpack field header field \":status\" = \"200\"
2019-05-17T12:44:52.118961-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json\"
2019-05-17T12:44:52.119014-04:00 http2: decoded hpack field header field \"content-length\" = \"224\"
2019-05-17T12:44:52.11905-04:00 http2: decoded hpack field header field \"date\" = \"Fri, 17 May 2019 16:44:52 GMT\"
2019-05-17T12:44:52.119087-04:00 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.11916-04:00 http2: Framer 0xc000272700: read DATA flags=END_STREAM stream=1 len=224 data="redacted"
2019-05-17T12:44:52.119196-04:00 http2: Transport received DATA flags=END_STREAM stream=1 len=224 data="redacted"
2019-05-17T12:44:52.125208-04:00 http2: Transport creating client conn 0xc0003e6c00 to 127.0.0.1:8443
2019-05-17T12:44:52.125271-04:00 http2: Framer 0xc0004927e0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019-05-17T12:44:52.12532-04:00 http2: Framer 0xc0004927e0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019-05-17T12:44:52.125359-04:00 http2: Transport encoding header \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.125395-04:00 http2: Framer 0xc0004927e0: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019-05-17T12:44:52.125456-04:00 http2: Transport encoding header \":method\" = \"POST\"
2019-05-17T12:44:52.125512-04:00 http2: Transport encoding header \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.125545-04:00 http2: Transport encoding header \":scheme\" = \"https\"
2019-05-17T12:44:52.125577-04:00 http2: Transport encoding header \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.125609-04:00 http2: Transport encoding header \"content-length\" = \"258\"
2019-05-17T12:44:52.125647-04:00 http2: Transport encoding header \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.125689-04:00 http2: Transport encoding header \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.12572-04:00 http2: Framer 0xc0004927e0: wrote HEADERS flags=END_HEADERS stream=1 len=78
2019-05-17T12:44:52.125759-04:00 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019-05-17T12:44:52.125802-04:00 http2: Framer 0xc0004927e0: wrote SETTINGS flags=ACK len=0
2019-05-17T12:44:52.125829-04:00 http2: Framer 0xc0004927e0: read WINDOW_UPDATE len=4 (conn) incr=983041
2019-05-17T12:44:52.125852-04:00 http2: Framer 0xc0004927e0: wrote DATA flags=END_STREAM stream=1 len=0 data="redacted"
2019-05-17T12:44:52.125898-04:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2019-05-17T12:44:52.125949-04:00 http2: Framer 0xc0004927e0: read SETTINGS flags=ACK len=0
2019-05-17T12:44:52.125987-04:00 http2: Transport received SETTINGS flags=ACK len=0
2019-05-17T12:44:52.126523-04:00 http2: Transport encoding header \":authority\" = \"localhost:8443\"
2019-05-17T12:44:52.126554-04:00 http2: Transport encoding header \":method\" = \"POST\"
2019-05-17T12:44:52.126586-04:00 http2: Transport encoding header \":path\" = \"/api/sessions/authenticate\"
2019-05-17T12:44:52.12661-04:00 http2: Transport encoding header \":scheme\" = \"https\"
2019-05-17T12:44:52.126639-04:00 http2: Transport encoding header \"content-type\" = \"application/json; utf-8\"
2019-05-17T12:44:52.126679-04:00 http2: Transport encoding header \"content-length\" = \"258\"
2019-05-17T12:44:52.126701-04:00 http2: Transport encoding header \"accept-encoding\" = \"gzip\"
2019-05-17T12:44:52.126728-04:00 http2: Framer 0xc0004927e0: read HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.126764-04:00 http2: Transport encoding header \"user-agent\" = \"Go-http-client/2.0\"
2019-05-17T12:44:52.1268-04:00 http2: Framer 0xc0004927e0: wrote HEADERS flags=END_HEADERS stream=3 len=8
2019-05-17T12:44:52.126845-04:00 http2: decoded hpack field header field \":status\" = \"400\"
2019-05-17T12:44:52.127143-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json\"
2019-05-17T12:44:52.127383-04:00 http2: Framer 0xc0004927e0: wrote DATA stream=3 len=258 data="redacted"
2019-05-17T12:44:52.127587-04:00 http2: decoded hpack field header field \"content-length\" = \"86\"
2019-05-17T12:44:52.12762-04:00 http2: Framer 0xc0004927e0: wrote DATA flags=END_STREAM stream=3 len=0 data="redacted"
2019-05-17T12:44:52.127654-04:00 http2: decoded hpack field header field \"date\" = \"Fri, 17 May 2019 16:44:52 GMT\"
2019-05-17T12:44:52.127687-04:00 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=42
2019-05-17T12:44:52.127749-04:00 http2: Framer 0xc0004927e0: read DATA flags=END_STREAM stream=1 len=86 data="redacted"
2019-05-17T12:44:52.127791-04:00 http2: Transport received DATA flags=END_STREAM stream=1 len=86 data="redacted"
2019-05-17T12:44:52.127823-04:00 http2: Framer 0xc0004927e0: read WINDOW_UPDATE len=4 (conn) incr=258
2019-05-17T12:44:52.12784-04:00 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=258
2019-05-17T12:44:52.127884-04:00 http2: Framer 0xc0004927e0: read WINDOW_UPDATE stream=3 len=4 incr=258
2019-05-17T12:44:52.12791-04:00 http2: Transport received WINDOW_UPDATE stream=3 len=4 incr=258
2019-05-17T12:44:52.131423-04:00 http2: Framer 0xc0004927e0: read GOAWAY len=8 LastStreamID=3 ErrCode=NO_ERROR Debug=\"\"
2019-05-17T12:44:52.131459-04:00 http2: Transport received GOAWAY len=8 LastStreamID=3 ErrCode=NO_ERROR Debug=\"\"
2019-05-17T12:44:52.13163-04:00 http2: Framer 0xc0004927e0: read HEADERS flags=END_HEADERS stream=3 len=7
2019-05-17T12:44:52.131665-04:00 http2: decoded hpack field header field \":status\" = \"200\"
2019-05-17T12:44:52.131697-04:00 http2: decoded hpack field header field \"content-type\" = \"application/json\"
2019-05-17T12:44:52.13173-04:00 http2: decoded hpack field header field \"content-length\" = \"224\"
2019-05-17T12:44:52.131759-04:00 http2: decoded hpack field header field \"date\" = \"Fri, 17 May 2019 16:44:52 GMT\"
2019-05-17T12:44:52.131788-04:00 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=7
2019-05-17T12:44:52.131851-04:00 http2: Framer 0xc0004927e0: read DATA flags=END_STREAM stream=3 len=224 data="redacted"
2019-05-17T12:44:52.131896-04:00 http2: Transport received DATA flags=END_STREAM stream=3 len=224 data="redacted"
2019-05-17T12:44:52.13703-04:00 http2: Transport failed to get client conn for localhost:8443: http2: no cached connection was available
@bcmills

This comment has been minimized.

Copy link
Member

commented May 20, 2019

CC @bradfitz @tombergan

Per §8.1.2.2:

HTTP/2 does not use the Connection header field to indicate connection-specific header fields; in this protocol, connection-specific metadata is conveyed by other means. An endpoint MUST NOT generate an HTTP/2 message containing connection-specific header fields; any message containing connection-specific header fields MUST be treated as malformed (Section 8.1.2.6).

I don't see anything in the x/net/http2 or x/net documentation that suggests an exception to this rule.

I don't know whether there is a documented, supported way to provoke a Go HTTP/2 server to gracefully close the connection after serving a request, but Connection: close does not appear to be it.

@bcmills bcmills added this to the Unplanned milestone May 20, 2019
@bradfitz

This comment has been minimized.

Copy link
Member

commented May 20, 2019

@bcmills, the http2 server already maps a Handler's Connection: close response to a GOAWAY, as the OP referenced in their comment.

The x/net/http2/server.go code is:

                // "Connection" headers aren't allowed in HTTP/2 (RFC 7540, 8.1.2.2),                                                                                                    
                // but respect "Connection" == "close" to mean sending a GOAWAY and tearing                                                                                              
                // down the TCP connection when idle, like we do for HTTP/1.                                                                                                             
                // TODO: remove more Connection-specific header fields here, in addition                                                                                                 
                // to "Connection".                                                                                                                                                      
                if _, ok := rws.snapHeader["Connection"]; ok {
                        v := rws.snapHeader.Get("Connection")
                        delete(rws.snapHeader, "Connection")
                        if v == "close" {
                                rws.conn.startGracefulShutdown()
                        }
                }
@bradfitz

This comment has been minimized.

Copy link
Member

commented May 20, 2019

This looks like the server & client were both speaking at the ~same time and had messages that crossed paths in flight:

The server was sending:

GOAWAY

The client was sending:

HEADERS+DATA (a POST request with a body)

The server got the HEADERS and ignored it, since it was already inGoAway state, and just assumed that the client might've already had that in flight.

func (sc *serverConn) processHeaders(f *MetaHeadersFrame) error {
        sc.serveG.check()
        id := f.StreamID
        if sc.inGoAway {
                // Ignore. 
                return nil
        }

But it seems like that safety measure was only added for GET requests, because when we get the POST requests body in te DATA frame:

func (sc *serverConn) processData(f *DataFrame) error {
        sc.serveG.check()
        if sc.inGoAway && sc.goAwayCode != ErrCodeNo {
                return nil
        }
        data := f.Data()

        // "If a DATA frame is received whose stream is not in "open"
        // or "half closed (local)" state, the recipient MUST respond
        // with a stream error (Section 5.4.2) of type STREAM_CLOSED."
        id := f.Header().StreamID
        state, st := sc.state(id)
        if id == 0 || state == stateIdle {
                // Section 5.1: "Receiving any frame other than HEADERS
                // or PRIORITY on a stream in this state MUST be
                // treated as a connection error (Section 5.4.1) of
                // type PROTOCOL_ERROR."
                return ConnectionError(ErrCodeProtocol)
        }

I don't remember why the sc.goAwayCode != ErrCodeNo check is there. But that looks like the problem because our error code is ErrCodeNo, and thus we're hitting the ErrCodeProtocol at the bottom there.

@bradfitz

This comment has been minimized.

Copy link
Member

commented May 20, 2019

Looks like it was added in golang/net@569280f

@mightyguava

This comment has been minimized.

Copy link
Author

commented May 21, 2019

Not sure if it's related, but in the server handler, I also occasionally saw errors like request declared a Content-Length of 258 but only wrote 0 bytes reading the request body

@mightyguava

This comment has been minimized.

Copy link
Author

commented Jun 11, 2019

@bcmills @bradfitz any plans to fix this? I can take a stab at it too if you want to give me some pointers.

@gopherbot

This comment has been minimized.

Copy link

commented Aug 1, 2019

Change https://golang.org/cl/188360 mentions this issue: http2: discard DATA frames with higher stream IDs during graceful shutdown

@mightyguava

This comment has been minimized.

Copy link
Author

commented Aug 27, 2019

@bradfitz @tombergan @bcmills this tiny CL has been open for almost a month now. It's mostly documentation updates with a tiny bug fix. Would one of you mind reviewing?

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 27, 2019

I've been on parental leave for 3 months. I'm just back at work and catching up.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.