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

Closed
mightyguava opened this issue May 17, 2019 · 13 comments
Closed

x/net/http2: PROTOCOL_ERROR after GOAWAY #32112

mightyguava opened this issue May 17, 2019 · 13 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@mightyguava
Copy link

mightyguava 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
Copy link
Contributor

bcmills 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 the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 20, 2019
@bcmills bcmills added this to the Unplanned milestone May 20, 2019
@bradfitz
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Contributor

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

@mightyguava
Copy link
Author

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
Copy link
Author

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

@gopherbot
Copy link

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

@mightyguava
Copy link
Author

@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
Copy link
Contributor

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

@mightyguava
Copy link
Author

@bradfitz got time to give a final stamp? Andrew already gave a +1. It's a super tiny change that I'd really love to close out. Should only take a moment of your time.

@bradfitz
Copy link
Contributor

bradfitz commented Nov 6, 2019

@mightyguava, it needs a test.

@gopherbot
Copy link

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

@gopherbot
Copy link

Change https://golang.org/cl/296789 mentions this issue: all: update golang.org/x/* dependencies

gopherbot pushed a commit that referenced this issue Mar 15, 2021
Updates src/ and src/cmd/* dependencies, using

    go mod vendor

as well as

    updatestd -branch=master -goroot=$GOROOT

This change was ran in anticipation of bringing in x/net/http2 CL 237957.

For #32112.
For #36905.

Change-Id: If8cefc348463b6d82d85020b57db411213720ef8
Reviewed-on: https://go-review.googlesource.com/c/go/+/296789
Trust: Emmanuel Odeke <emmanuel@orijtech.com>
Trust: Dmitri Shuralyov <dmitshur@golang.org>
Trust: Bryan C. Mills <bcmills@google.com>
Run-TryBot: Emmanuel Odeke <emmanuel@orijtech.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Alexander Rakoczy <alex@golang.org>
@golang golang locked and limited conversation to collaborators Mar 13, 2022
dteh pushed a commit to dteh/fhttp that referenced this issue Jun 22, 2022
…tdown

If the server sends a GOAWAY at the same time that a client sends
HEADERS+DATA, the server will discard the HEADERS, but error on the DATA
frame. Luckily, the server doesn't turn this into a connection error
because it's already in a GOAWAY state. It just logs the PROTOCOL_ERROR,
but that produces a confusing log message.

This change effectively suppresses the log message by discarding the
DATA frame rather than erroring on it. Also, we now discard any frames for
streams with identifiers higher than the identified last stream. This is
done as per section 6.8 of the HTTP2 spec.

I also updated some stale documentation while I was trying to understand
the logic.

This is CL 188360 with a test

Fixes golang/go#32112

Co-authored-by: Yunchi Luo <mightyguava@gmail.com>
Co-authored-by: Michael Fraenkel <michael.fraenkel@gmail.com>

Change-Id: I612c2bd82e37551e813af0961b16a98d14e77c38
Reviewed-on: https://go-review.googlesource.com/c/net/+/237957
Run-TryBot: Agniva De Sarker <agniva.quicksilver@gmail.com>
Run-TryBot: Emmanuel Odeke <emmanuel@orijtech.com>
Reviewed-by: Emmanuel Odeke <emmanuel@orijtech.com>
TryBot-Result: Go Bot <gobot@golang.org>
Trust: Damien Neil <dneil@google.com>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

4 participants