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: EOF when Transport received GOAWAY (http2 client) #14627

Closed
nathany opened this issue Mar 3, 2016 · 22 comments
Closed

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

nathany opened this issue Mar 3, 2016 · 22 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@nathany
Copy link
Contributor

nathany commented Mar 3, 2016

Please answer these questions before submitting your issue. Thanks!

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

go version go1.6 darwin/amd64

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

GOHOSTARCH="amd64"
GOHOSTOS="darwin"

  1. 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

  1. 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
  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

@nathany 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 bradfitz self-assigned this Apr 9, 2016
@bradfitz bradfitz added this to the Go1.7 milestone Apr 9, 2016
@bradfitz
Copy link
Contributor

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

nathany commented May 20, 2016

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 bradfitz modified the milestones: Go1.7Maybe, Go1.7 May 20, 2016
@bradfitz
Copy link
Contributor

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

nathany commented May 20, 2016

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

nathany commented Jun 15, 2016

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

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

gopherbot pushed a commit to golang/net that referenced this issue Jun 28, 2016
Updates golang/go#14627 (fixes once bundled into std)

Change-Id: Iae91d165df749e06549a25f9664ee416f115573f
Reviewed-on: https://go-review.googlesource.com/24560
Reviewed-by: Andrew Gerrand <adg@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@gopherbot
Copy link

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

@nathany
Copy link
Contributor Author

nathany commented Jun 29, 2016

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

@nathany
Copy link
Contributor Author

nathany commented Jun 29, 2016

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

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

@bradfitz
Copy link
Contributor

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

@nathany
Copy link
Contributor Author

nathany commented Jun 29, 2016

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

@nathany
Copy link
Contributor Author

nathany commented Jun 29, 2016

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

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

@bradfitz
Copy link
Contributor

I'm happy enough.

@bradfitz
Copy link
Contributor

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

@nathany
Copy link
Contributor Author

nathany commented Jun 29, 2016

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

nathany commented Jun 29, 2016

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

nathany commented Jun 29, 2016

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

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

nathany commented Jun 29, 2016

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.

gopherbot pushed a commit to golang/net that referenced this issue Jun 29, 2016
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 <bradfitz@golang.org>
Reviewed-by: Andrew Gerrand <adg@golang.org>
gopherbot pushed a commit that referenced this issue Jun 30, 2016
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 <bradfitz@golang.org>
Reviewed-by: Andrew Gerrand <adg@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@gopherbot
Copy link

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

@golang golang locked and limited conversation to collaborators Jun 30, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

3 participants