search

golang / go

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

x/net/http2: PROTOCOL_ERROR after GOAWAY #32112

Closed mightyguava closed 3 years ago

mightyguava commented 5 years ago

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

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.

bradfitz commented 5 years ago

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

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

Looks like it was added in https://github.com/golang/net/commit/569280fa63be4e201b975e5411e30a92178f0118

mightyguava commented 5 years ago

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

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

gopherbot commented 5 years ago

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

mightyguava commented 5 years ago

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

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

mightyguava commented 4 years ago

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

@mightyguava, it needs a test.

gopherbot commented 4 years ago

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

gopherbot commented 3 years ago

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