x/net/http2: certain HTTP2 requests sends a "END_STREAM" prematurely

[corgrath]

Our organization is using a Go backend in order to send POST API requests to various HTTPS end points.

The example below is for a service called Iterable (api.iterable.com:443), but we see similar problems with others hosts, so we believe there is a problem with the Go HTTP2 stack, somehow. But we are unsure what to look at in order to understand what the causes our failed requests on our environment.

We have noticed that every once and a while, a request just breaks and we get back from Amazon Web Service a 400 BAD REQUEST.

In order to figure out why, I have enabled GODEBUG=http2debug=2 and I am comparing a failed request against a succeeding requests.

I see a pattern where a failing requests does a END_STREAM prematurely, before sending the data, while working requests sends its data, then END_STREAM.

However, we can send two requests after each other, same code, same payload and one succeeds and the other might fail.

We have not yet figured out why.

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

1.11

Does this issue reproduce with the latest release?

N/A

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/prodmd/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/prodmd/go"
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build716194233=/tmp/go-build -gno-record-gcc-switches"

What did you expect to see?

Having GODEBUG=http2debug=2 enabled, I am trying to figure out why certain Go HTTP2 requests fail, while others succeed.

The definition of a failed requests is that Amazon Web Services is sending a 400 BAD REQUEST, while 200 on others.

Our code is static, the payload might change, but according to the dump, our payload is not event sent before AWS closes down the client.

A working request 1

E  2018/10/11 11:40:13 http2: Transport failed to get client conn for api.iterable.com:443: http2: no cached connection was available
E  2018/10/11 11:40:14 http2: Transport creating client conn 0xc000195500 to 52.6.82.185:443
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
E  2018/10/11 11:40:14 http2: Transport encoding header ":authority" = "api.iterable.com:443"
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 11:40:14 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 11:40:14 http2: Transport encoding header ":method" = "POST"
E  2018/10/11 11:40:14 http2: Transport encoding header ":path" = "/api/users/registerDeviceToken?api_key=REMOVED&trace=3a1d2c47-7d39-4e53-94b9-37aeae30fc8d"
E  2018/10/11 11:40:14 http2: Transport encoding header ":scheme" = "https"
E  2018/10/11 11:40:14 http2: Transport encoding header "content-type" = "application/json"
E  2018/10/11 11:40:14 http2: Transport encoding header "content-length" = "269"
E  2018/10/11 11:40:14 http2: Transport encoding header "accept-encoding" = "gzip"
E  2018/10/11 11:40:14 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote HEADERS flags=END_HEADERS stream=1 len=140
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote DATA stream=1 len=269 data="{\"userId\":\"32fd40ba-02fc-4c97-baa0-e847e96212a0\",\"device\":{\"platform\":\"GCM\",\"applicationName\":\"gcm_ios\",\"token\":\"REMOVED" (13 bytes omitted)
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote SETTINGS flags=ACK len=0
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote DATA flags=END_STREAM stream=1 len=0 data=""
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 11:40:14 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read SETTINGS flags=ACK len=0
E  2018/10/11 11:40:14 http2: Transport received SETTINGS flags=ACK len=0
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read WINDOW_UPDATE stream=1 len=4 incr=269
E  2018/10/11 11:40:14 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=269
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read HEADERS flags=END_HEADERS stream=1 len=96
E  2018/10/11 11:40:14 http2: decoded hpack field header field ":status" = "200"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "date" = "Thu, 11 Oct 2018 11:40:14 GMT"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "content-type" = "application/json"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "content-length" = "65"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "vary" = "Origin,Accept-Encoding"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "request-time" = "37"
E  2018/10/11 11:40:14 http2: decoded hpack field header field "content-encoding" = "gzip"
E  2018/10/11 11:40:14 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=96
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read DATA stream=1 len=65 data="REMOVED"
E  2018/10/11 11:40:14 http2: Transport received DATA stream=1 len=65 data="REMOVED"
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: read DATA flags=END_STREAM stream=1 len=0 data=""
E  2018/10/11 11:40:14 http2: Transport received DATA flags=END_STREAM stream=1 len=0 data=""

A working request 2

E  2018/10/11 12:03:13 http2: Transport failed to get client conn for api.iterable.com:443: http2: no cached connection was available
E  2018/10/11 12:03:13 http2: Framer 0xc0005890a0: read GOAWAY len=8 LastStreamID=91 ErrCode=NO_ERROR Debug=""
E  2018/10/11 12:03:13 http2: Transport received GOAWAY len=8 LastStreamID=91 ErrCode=NO_ERROR Debug=""
E  2018/10/11 12:03:13 http2: Transport readFrame error on conn 0xc000195500: (*errors.errorString) EOF
E  2018/10/11 12:03:13 http2: Framer 0xc000589500: read GOAWAY len=8 LastStreamID=17 ErrCode=NO_ERROR Debug=""
E  2018/10/11 12:03:13 http2: Transport received GOAWAY len=8 LastStreamID=17 ErrCode=NO_ERROR Debug=""
E  2018/10/11 12:03:13 http2: Transport readFrame error on conn 0xc00052d500: (*errors.errorString) EOF
E  2018/10/11 12:03:14 http2: Transport creating client conn 0xc00052dc00 to 52.6.82.185:443
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
E  2018/10/11 12:03:14 http2: Transport encoding header ":authority" = "api.iterable.com:443"
E  2018/10/11 12:03:14 http2: Transport encoding header ":method" = "POST"
E  2018/10/11 12:03:14 http2: Transport encoding header ":path" = "/api/users/registerDeviceToken?api_key=REMOVED&trace=10f1f93f-d6d8-4f4e-85b7-92f5728b65aa"
E  2018/10/11 12:03:14 http2: Transport encoding header ":scheme" = "https"
E  2018/10/11 12:03:14 http2: Transport encoding header "content-type" = "application/json"
E  2018/10/11 12:03:14 http2: Transport encoding header "content-length" = "291"
E  2018/10/11 12:03:14 http2: Transport encoding header "accept-encoding" = "gzip"
E  2018/10/11 12:03:14 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote HEADERS flags=END_HEADERS stream=1 len=139
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 12:03:14 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote SETTINGS flags=ACK len=0
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: read WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 12:03:14 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote DATA stream=1 len=291 data="{\"userId\":\"2b6970ac-4a75-41c5-ab3b-fbbc0ff134c5\",\"device\":{\"platform\":\"GCM\",\"applicationName\":\"gcm_ios\",\"token\":\"REMOVED" (35 bytes omitted)
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote DATA flags=END_STREAM stream=1 len=0 data=""

A failing request

E  2018/10/11 11:31:12 http2: Transport failed to get client conn for api.iterable.com:443: http2: no cached connection was available
E  2018/10/11 11:31:13 http2: Transport creating client conn 0xc000195c00 to 52.6.82.185:443
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
E  2018/10/11 11:31:13 http2: Transport encoding header ":authority" = "api.iterable.com:443"
E  2018/10/11 11:31:13 http2: Transport encoding header ":method" = "POST"
E  2018/10/11 11:31:13 http2: Transport encoding header ":path" = "/api/users/registerDeviceToken?api_key=REMOVED&trace=0f06c1a3-c3fc-44a5-a9ec-c658b281dc8f"
E  2018/10/11 11:31:13 http2: Transport encoding header ":scheme" = "https"
E  2018/10/11 11:31:13 http2: Transport encoding header "content-type" = "application/json"
E  2018/10/11 11:31:13 http2: Transport encoding header "content-length" = "273"
E  2018/10/11 11:31:13 http2: Transport encoding header "accept-encoding" = "gzip"
E  2018/10/11 11:31:13 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote HEADERS flags=END_HEADERS stream=1 len=139
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote DATA flags=END_STREAM stream=1 len=0 data=""
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 11:31:13 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote SETTINGS flags=ACK len=0
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: read WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 11:31:13 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: read SETTINGS flags=ACK len=0
E  2018/10/11 11:31:13 http2: Transport received SETTINGS flags=ACK len=0
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: read HEADERS flags=END_HEADERS stream=1 len=48
E  2018/10/11 11:31:13 http2: decoded hpack field header field ":status" = "400"
E  2018/10/11 11:31:13 http2: decoded hpack field header field "server" = "awselb/2.0"
E  2018/10/11 11:31:13 http2: decoded hpack field header field "date" = "Thu, 11 Oct 2018 11:31:13 GMT"
E  2018/10/11 11:31:13 http2: decoded hpack field header field "content-type" = "text/html"
E  2018/10/11 11:31:13 http2: decoded hpack field header field "content-length" = "138"
E  2018/10/11 11:31:13 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=48
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: read DATA flags=END_STREAM stream=1 len=138 data="<html>\r\n<head><title>400 Bad Request</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>400 Bad Request</h1></center>\r\n</body>\r\n</html>\r\n"
E  2018/10/11 11:31:13 http2: Transport received DATA flags=END_STREAM stream=1 len=138 data="<html>\r\n<head><title>400 Bad Request</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>400 Bad Request</h1></center>\r\n</body>\r\n</html>\r\n"
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote RST_STREAM stream=1 len=4 ErrCode=CANCEL

Comparison

When I compare the two dumps side by side, the only significant changes I see is that the read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215 comes earlier in the working request, but later in the failing one.

Another significant change is that on the failing requests, you can see:

E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote HEADERS flags=END_HEADERS stream=1 len=139
E  2018/10/11 11:31:13 http2: Framer 0xc000589260: wrote DATA flags=END_STREAM stream=1 len=0 data=""

But on the working, the data is actually sent before END_STREAM;

Working request 1:

E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote HEADERS flags=END_HEADERS stream=1 len=140
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote DATA stream=1 len=269 data="{\"userId\":\"32fd40ba-02fc-4c97-baa0-e847e96212a0\",\"device\":{\"platform\":\"GCM\",\"applicationName\":\"gcm_ios\",\"token\":\"REMOVED" (13 bytes omitted)
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote SETTINGS flags=ACK len=0
E  2018/10/11 11:40:14 http2: Framer 0xc0005890a0: wrote DATA flags=END_STREAM stream=1 len=0 data=""

Working request 2:

E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote DATA stream=1 len=291 data="{\"userId\":\"2b6970ac-4a75-41c5-ab3b-fbbc0ff134c5\",\"device\":{\"platform\":\"GCM\",\"applicationName\":\"gcm_ios\",\"token\":\"REMOVED" (35 bytes omitted)
E  2018/10/11 12:03:14 http2: Framer 0xc0000b8e00: wrote DATA flags=END_STREAM stream=1 len=0 data=""

But I don't know why.

My questions

I am not familiar with these dumps and how to read them, but I have two questions:

1. Is there anything in the dumps that can explain why Go HTTP2 sends a premature END_STREAM on certain requests, but manages to send the payload on the others?

2. We are using http.NewRequest(method, url string, body io.Reader) which has if req.GetBody != nil && req.ContentLength == 0 { so, if we were indeed sending empty data (which Ive tripled checked), this would have stopped it right (?). Is there anything GODEBUG=http2debug=2 that can testify there is a payload in the POST request?

Any feedback would be appreciated!

[fraenkel]

It might be a dupe of #25009. When retrying a POST with http/2, the body was not reset on the new request.

[FiloSottile]

/cc @bradfitz

[odeke-em]

Also kindly paging @rs @meirf too

[rs]

Are you able to provide a sample code reproducing the issue?

[corgrath]

I wish I could.

The problem is not deterministic, it happens sporadically. I am not even unable to recreate this locally on my developer Mac computer using the same code. I have only been able to debug this directly in production where we have deployed our app on GCP Kubernetes.

I don't know why.

[corgrath]

Just a quick update regarding this issue;

We've been doing tests by changing the client implementations, and we have noticed when using ..

• A strict HTTP 1.1 client (which uses an empty http.Transport{TLSNextProto:...} transport) - no errors
• A strict HTTP 2 client (which uses http2.Transport{} transport) - no errors
• http.DefaultTransport - we randomly get errors, this is most likely because of the linked issue saying (from what I understand) when the connection upgrades to HTTP 2, it breaks when trying to resend the data

[ernado]

I'm pretty sure that it is a dupe of #25009.
@corgrath is it possible for you to try the go1.12 beta?
The fix for that issue is already merged and will be available in go1.12.

[ernado]

@corgrath any news? :)

Actually I think that we can close this.

[corgrath]

We are not running 1.12 in production yet, so I haven't been able to verify this with HTTP2, but sure, it can get closed.

[agnivade]

Closing then. Please feel free to reopen if you see this again with 1.12. Thanks