x/net/http2: EOF when Transport received GOAWAY (http2 client) #14627

nathany · 2016-03-03T20:55:54Z

Please answer these questions before submitting your issue. Thanks!

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

go version go1.6 darwin/amd64

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

GOHOSTARCH="amd64"
GOHOSTOS="darwin"

What did you do?

Run Buford's push example with a development certificate against the production environment.

buford/example/push
❯ GODEBUG=http2debug=2 go run main.go -c cert.p12 -d device-token -e production

RobotsAndPencils/buford#33

What did you expect to see?

Expected a status code and JSON response {"reason":"BadCertificateEnvironment"}

This is the debug output from a similar request:

http2: Transport failed to get client conn for api.development.push.apple.com:443: http2: no cached connection was available
http2: Transport creating client conn to 17.172.238.203:443
http2: Framer 0xc82049fbc0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
http2: Framer 0xc82049fbc0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
http2: Framer 0xc82049fbc0: read SETTINGS len=24, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=500, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=8000
http2: Framer 0xc82049fbc0: wrote SETTINGS flags=ACK len=0
Unhandled Setting: [HEADER_TABLE_SIZE = 4096]
Unhandled Setting: [MAX_HEADER_LIST_SIZE = 8000]
http2: Transport encoding header ":authority" = "api.development.push.apple.com"
http2: Transport encoding header ":method" = "POST"
http2: Transport encoding header ":path" = "/3/device/device-token"
http2: Transport encoding header ":scheme" = "https"
http2: Transport encoding header "content-type" = "application/json"
http2: Transport encoding header "content-length" = "43"
http2: Transport encoding header "accept-encoding" = "gzip"
http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
http2: Framer 0xc82049fbc0: wrote HEADERS flags=END_HEADERS stream=1 len=81
http2: Framer 0xc82049fbc0: wrote DATA stream=1 len=43 data="{\"aps\":{\"alert\":\"Hello HTTP/2\",\"badge\":42}}"
http2: Framer 0xc82049fbc0: wrote DATA flags=END_STREAM stream=1 len=0 data=""
http2: Framer 0xc82049fbc0: read SETTINGS flags=ACK len=0
http2: Transport received SETTINGS flags=ACK len=0
http2: Framer 0xc82049fbc0: read HEADERS flags=END_HEADERS stream=1 len=1
http2: Transport received HEADERS flags=END_HEADERS stream=1 len=1
http2: Framer 0xc82049fbc0: read DATA flags=END_STREAM stream=1 len=27 data="{\"reason\":\"BadDeviceToken\"}"
http2: Transport received DATA flags=END_STREAM stream=1 len=27 data="{\"reason\":\"BadDeviceToken\"}"
bad device token
exit status 1

What did you see instead?

Client.Do(req) returned an EOF error.

http2: Transport failed to get client conn for api.push.apple.com:443: http2: no cached connection was available
http2: Transport creating client conn to 17.110.227.90:443
http2: Framer 0xc8204a1080: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
http2: Framer 0xc8204a1080: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
http2: Framer 0xc8204a1080: read SETTINGS len=24, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=500, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=8000
http2: Framer 0xc8204a1080: wrote SETTINGS flags=ACK len=0
Unhandled Setting: [HEADER_TABLE_SIZE = 4096]
Unhandled Setting: [MAX_HEADER_LIST_SIZE = 8000]
http2: Transport encoding header ":authority" = "api.push.apple.com"
http2: Transport encoding header ":method" = "POST"
http2: Transport encoding header ":path" = "/3/device/device-token"
http2: Transport encoding header ":scheme" = "https"
http2: Transport encoding header "content-type" = "application/json"
http2: Transport encoding header "content-length" = "43"
http2: Transport encoding header "accept-encoding" = "gzip"
http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
http2: Framer 0xc8204a1080: wrote HEADERS flags=END_HEADERS stream=1 len=72
http2: Framer 0xc8204a1080: wrote DATA stream=1 len=43 data="{\"aps\":{\"alert\":\"Hello HTTP/2\",\"badge\":42}}"
http2: Framer 0xc8204a1080: wrote DATA flags=END_STREAM stream=1 len=0 data=""
http2: Framer 0xc8204a1080: read GOAWAY len=46 LastStreamID=0 ErrCode=NO_ERROR Debug="{\"reason\":\"BadCertificateEnvironment\"}"
http2: Transport received GOAWAY len=46 LastStreamID=0 ErrCode=NO_ERROR Debug="{\"reason\":\"BadCertificateEnvironment\"}"
http2: Framer 0xc8204a1080: read GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
Transport readFrame error: (*errors.errorString) EOF
RoundTrip failure: unexpected EOF
Post https://api.push.apple.com/3/device/device-token: unexpected EOF
exit status 1

We're not sure if this is an issue with how x/net/http2 is handling GOAWAY and/or a problem with how Apple is returning this particular error.

/cc @groob

The text was updated successfully, but these errors were encountered:

bradfitz · 2016-05-20T15:10:49Z

So Apple is sometimes returning errors in DATA frames, and sometimes in GOAWAY frames?

I suppose we could note the most recent GOAWAY debug message (if any) and hold on to it if that ends up being the best possible way to fail your RoundTrip at EOF, if nothing more explicit hasn't come up in the meantime.

nathany · 2016-05-20T15:24:37Z

Yah. I don't know why Apple is returning errors in GOAWAY frames. I just ran the test again to confirm that it is still the case.

I'm not familiar with the HTTP/2 specification. Should I open an issue with Apple as to why they are returning errors in GOAWAY or is that a legit thing to do? Some way of accessing the GOAWAY debug message from Go could be useful, but do note that there are GOAWAY frames with no debug message after the ones with one.

Alternatively I could just handle EOF and document that people should use GODEBUG=http2debug=2 for further detail.

bradfitz · 2016-05-20T15:30:42Z

No need to bug Apple. This is fine, if slightly unique behavior.

I've demoted this to Go1.7Maybe because I believe you use x/net/http2 directly anyway, so timing doesn't matter as much. Also, I disappear for a month in approximately 8 hours.

nathany · 2016-05-20T15:37:14Z

Works for me. Yes, using an Apple-signed certificate requires that I bring in x/net/http2 and use http2.ConfigureTransport. Hope you have a wonderful month away.

nathany · 2016-06-15T21:42:30Z

Update: Later this year I hope to be able to use net/http rather than x/net/http2 in cases where I don't need to setup a different certificate for the client. This is thanks to the Apple introducing JSON Web Tokens for Authentication rather than relying on certificates signed by them. If I could just use net/http even with a different cert, that would be great too, but a separate issue.

bradfitz · 2016-06-28T23:01:27Z

Sent https://golang.org/cl/24560

Updates golang/go#14627 (fixes once bundled into std) Change-Id: Iae91d165df749e06549a25f9664ee416f115573f Reviewed-on: https://go-review.googlesource.com/24560 Reviewed-by: Andrew Gerrand <[email protected]> Run-TryBot: Brad Fitzpatrick <[email protected]> TryBot-Result: Gobot Gobot <[email protected]>

gopherbot · 2016-06-29T00:00:18Z

CL https://golang.org/cl/24561 mentions this issue.

nathany · 2016-06-29T02:10:47Z

Thanks Brad. I'll test it out and report back.

nathany · 2016-06-29T16:23:19Z

Upon updating I no longer get the EOF error, but I'm still not seeing the GOAWAY response from Apple. This the error shown when using an incorrect certificate causing a GOAWAY response:

> go run main.go -c cert.p12 -d device_token -e production
Post https://api.push.apple.com/3/device/device_token: http2: server sent GOAWAY and closed the connection; LastStreamID=0, ErrCode=NO_ERROR, debug=""

The GODEBUG output is as follows:

❯ GODEBUG=http2debug=1 go run main.go -c ../../cert.p12 -d device_token -e production
2016/06/29 10:15:45 http2: Transport failed to get client conn for api.push.apple.com:443: http2: no cached connection was available
2016/06/29 10:15:46 http2: Transport creating client conn to 17.143.164.140:443
2016/06/29 10:15:46 Unhandled Setting: [HEADER_TABLE_SIZE = 4096]
2016/06/29 10:15:46 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 8000]
2016/06/29 10:15:46 http2: Transport encoding header ":authority" = "api.push.apple.com"
2016/06/29 10:15:46 http2: Transport encoding header ":method" = "POST"
2016/06/29 10:15:46 http2: Transport encoding header ":path" = "/3/device/device_token"
2016/06/29 10:15:46 http2: Transport encoding header ":scheme" = "https"
2016/06/29 10:15:46 http2: Transport encoding header "content-type" = "application/json"
2016/06/29 10:15:46 http2: Transport encoding header "content-length" = "43"
2016/06/29 10:15:46 http2: Transport encoding header "accept-encoding" = "gzip"
2016/06/29 10:15:46 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2016/06/29 10:15:46 http2: Transport received GOAWAY len=46 LastStreamID=0 ErrCode=NO_ERROR Debug="{\"reason\":\"BadCertificateEnvironment\"}"
2016/06/29 10:15:46 http2: Transport received GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2016/06/29 10:15:46 Transport readFrame error: (*errors.errorString) EOF
2016/06/29 10:15:46 RoundTrip failure: http2: server sent GOAWAY and closed the connection; LastStreamID=0, ErrCode=NO_ERROR, debug=""
Post https://api.push.apple.com/3/device/device_token: http2: server sent GOAWAY and closed the connection; LastStreamID=0, ErrCode=NO_ERROR, debug=""
exit status 1

As you can see, we receive more than one GOAWAY (despite only sending a single request). The first one contains Debug info whereas the later one does not.

ref: RobotsAndPencils/buford#33

I don't know whether it's worth trying to capture that error message. This change is already an improvement over the more generic EOF, and I can simply document what to look for when users see a GOAWAY error.

bradfitz · 2016-06-29T18:34:44Z

Sigh. I suppose we could track both the first and last or something. This is starting to feel very Apple-specific.

bradfitz · 2016-06-29T19:51:55Z

More: https://golang.org/cl/24600

nathany · 2016-06-29T19:53:33Z

It certainly does seem like an odd Apple thing, but I don't have experience with other HTTP/2 APIs to compare against.

nathany · 2016-06-29T19:58:47Z

I pulled your changeset which does what you intended.

Post https://api.push.apple.com/3/device/device_token: http2: server sent GOAWAY and closed the connection;
LastStreamID=0, ErrCode=NO_ERROR, debug="{\"reason\":\"BadCertificateEnvironment\"}"

Now I should be able to detect this error and parse the JSON in the debug parameter to return the appropriate error code "BadCertificateEnvironment".

Are you happy with that change though?

gopherbot · 2016-06-29T20:00:39Z

CL https://golang.org/cl/24600 mentions this issue.

bradfitz · 2016-06-29T20:02:20Z

I'm happy enough.

bradfitz · 2016-06-29T20:02:45Z

(Once I saw the spec mentions multiple GOAWAY frames, I didn't feel that it was too Apple specific anymore)

nathany · 2016-06-29T20:08:13Z

Thanks for exporting GoAwayError. That makes my job a lot easier.

Or at least it should. Haven't had any luck type asserting it back to GoAwayError yet.

resp, err := s.Client.Do(req)
if err != nil {
    if e, ok := err.(http2.GoAwayError); ok {
        log.Printf("GOAWAY %+v", e)
        return "", errors.New(e.DebugData)
    }
    return "", err
}

Go 1.7 beta2 (go version devel +fca9fc5 Thu Jun 16 19:45:33 2016 +0000 darwin/amd64)

It seems to not propagate up through to Client.Do. Somewhere "Post url" is being prepended to the text.

nathany · 2016-06-29T21:23:26Z

This does the trick:

resp, err := s.Client.Transport.RoundTrip(req)

Hopefully that doesn't miss out on anything important vs Client.Do, but it's not like I should need to follow redirects anyway. [update: well, nil Transport for DefaultClient, but no worries]

nathany · 2016-06-29T22:15:20Z

So here's the odd thing. After switching from Client.Do to calling RoundTrip directly, I'm only receiving one GOAWAY. Without CL https://go-review.googlesource.com/#/c/24600 applied, this is the output I now see:

❯ GODEBUG=http2debug=1 go run main.go -c ../../cert.p12 -d device_token -e production
2016/06/29 16:10:54 http2: Transport failed to get client conn for api.push.apple.com:443: http2: no cached connection was available
2016/06/29 16:10:54 http2: Transport creating client conn to 17.143.164.156:443
2016/06/29 16:10:54 Unhandled Setting: [HEADER_TABLE_SIZE = 4096]
2016/06/29 16:10:54 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 8000]
2016/06/29 16:10:54 http2: Transport encoding header ":authority" = "api.push.apple.com"
2016/06/29 16:10:54 http2: Transport encoding header ":method" = "POST"
2016/06/29 16:10:54 http2: Transport encoding header ":path" = "/3/device/device_token"
2016/06/29 16:10:54 http2: Transport encoding header ":scheme" = "https"
2016/06/29 16:10:54 http2: Transport encoding header "content-type" = "application/json"
2016/06/29 16:10:54 http2: Transport encoding header "content-length" = "43"
2016/06/29 16:10:54 http2: Transport encoding header "accept-encoding" = "gzip"
2016/06/29 16:10:54 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2016/06/29 16:10:54 http2: Transport received GOAWAY len=46 LastStreamID=0 ErrCode=NO_ERROR Debug="{\"reason\":\"BadCertificateEnvironment\"}"
2016/06/29 16:10:54 Transport readFrame error: (*errors.errorString) EOF
2016/06/29 16:10:54 RoundTrip failure: http2: server sent GOAWAY and closed the connection; LastStreamID=0, ErrCode=NO_ERROR, debug="{\"reason\":\"BadCertificateEnvironment\"}"
certificate was for the wrong environment
exit status 1

bradfitz · 2016-06-29T22:21:35Z

No clue. I don't control what Apple's server sends you. Maybe your request differed, or maybe you hit a different Apple backend. Or maybe it's a timing thing on their side.

nathany · 2016-06-29T22:27:30Z

Yah, hard to say. It doesn't seem like a bad idea to merge multiple GOAWAY errors regardless.

Thanks again for working on this. Much appreciated.

The http2 spec permits multiple GOAWAY frames if the conditions change. Merge their error messages together, preferring the first non-empty debug data, and first non-ErrCodeNo error code. Updates golang/go#14627 Change-Id: I073b9234d71f128ed0713f09a24c728b56d7c1ae Reviewed-on: https://go-review.googlesource.com/24600 Run-TryBot: Brad Fitzpatrick <[email protected]> Reviewed-by: Andrew Gerrand <[email protected]>

Updates x/net/http2 to git rev 8e573f40 for https://golang.org/cl/24600, "http2: merge multiple GOAWAY frames' contents into error message" Fixes #14627 (more) Change-Id: I5231607c2c9e0d854ad6199ded43c59e59f62f52 Reviewed-on: https://go-review.googlesource.com/24612 Run-TryBot: Brad Fitzpatrick <[email protected]> Reviewed-by: Andrew Gerrand <[email protected]> TryBot-Result: Gobot Gobot <[email protected]>

gopherbot · 2016-06-30T01:00:27Z

CL https://golang.org/cl/24585 mentions this issue.

nathany changed the title ~~x/net/http2: EOF when Transport received GOAWAY~~ x/net/http2: EOF when Transport received GOAWAY (http2 client) Mar 3, 2016

bradfitz self-assigned this Apr 9, 2016

bradfitz added this to the Go1.7 milestone Apr 9, 2016

bradfitz modified the milestones: Go1.7Maybe, Go1.7 May 20, 2016

bradfitz added help wanted NeedsFix The path to resolution is known, but the work has not been done. labels May 20, 2016

zmerlynn mentioned this issue May 23, 2016

On large cluster, routecontroller takes forever to program routes due to rate limit errors / reconcile kubernetes/kubernetes#26119

Closed

gopherbot closed this as completed in 8641e6f Jun 29, 2016

nathany mentioned this issue Jun 29, 2016

EOF error when there is a GOAWAY response RobotsAndPencils/buford#33

Closed

nathany mentioned this issue Jun 29, 2016

document GOAWAY errors from Apple RobotsAndPencils/buford#70

Merged

nathany mentioned this issue Jun 29, 2016

parse GOAWAY error responses from Apple RobotsAndPencils/buford#71

Merged

1 task

bradfitz removed the help wanted label Jun 29, 2016

golang locked and limited conversation to collaborators Jun 30, 2017

gopherbot added the FrozenDueToAge label Jun 30, 2017

rsc unassigned bradfitz Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

x/net/http2: EOF when Transport received GOAWAY (http2 client) #14627

x/net/http2: EOF when Transport received GOAWAY (http2 client) #14627

nathany commented Mar 3, 2016

bradfitz commented May 20, 2016

nathany commented May 20, 2016

bradfitz commented May 20, 2016

nathany commented May 20, 2016

nathany commented Jun 15, 2016 •

edited

Loading

bradfitz commented Jun 28, 2016

gopherbot commented Jun 29, 2016

nathany commented Jun 29, 2016

nathany commented Jun 29, 2016

bradfitz commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016

nathany commented Jun 29, 2016 •

edited

Loading

gopherbot commented Jun 29, 2016

bradfitz commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016 •

edited

Loading

nathany commented Jun 29, 2016 •

edited

Loading

nathany commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016

gopherbot commented Jun 30, 2016

x/net/http2: EOF when Transport received GOAWAY (http2 client) #14627

x/net/http2: EOF when Transport received GOAWAY (http2 client) #14627

Comments

nathany commented Mar 3, 2016

bradfitz commented May 20, 2016

nathany commented May 20, 2016

bradfitz commented May 20, 2016

nathany commented May 20, 2016

nathany commented Jun 15, 2016 • edited Loading

bradfitz commented Jun 28, 2016

gopherbot commented Jun 29, 2016

nathany commented Jun 29, 2016

nathany commented Jun 29, 2016

bradfitz commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016

nathany commented Jun 29, 2016 • edited Loading

gopherbot commented Jun 29, 2016

bradfitz commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016 • edited Loading

nathany commented Jun 29, 2016 • edited Loading

nathany commented Jun 29, 2016

bradfitz commented Jun 29, 2016

nathany commented Jun 29, 2016

gopherbot commented Jun 30, 2016

nathany commented Jun 15, 2016 •

edited

Loading

nathany commented Jun 29, 2016 •

edited

Loading

nathany commented Jun 29, 2016 •

edited

Loading

nathany commented Jun 29, 2016 •

edited

Loading