Skip to content

x/net/http2: MS Edge RST_STREAM cancel on a POST #19948

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.

Sign up for GitHub

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

Jump to bottom
Closed
hexadecy opened this issue Apr 12, 2017 · 25 comments
Closed

x/net/http2: MS Edge RST_STREAM cancel on a POST #19948

hexadecy opened this issue Apr 12, 2017 · 25 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.9Maybe

Comments

@hexadecy
Copy link

hexadecy commented Apr 12, 2017 •
edited
Loading

What version of Go are you using?

go version go1.8.1 windows/amd64

What operating system and processor architecture are you using?

set GOARCH=amd64
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
Windows version 10.0.14393

What did you do?

  1. Start a golang (1.6-1.8) server with http2 enabled and a valid tls certificate
  2. Open Microsoft EdgeHTML 14.14393 or Internet Explorer 11.1066.14393.0
  3. Do a POST resquest with Angular 1.5.10 using $resource or $http

What did you expect to see?

No error in browser console like in http1.
In chrome there is just one WINDOW_UPDATE:
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote WINDOW_UPDATE len=4 (conn) incr=176
and RST_STREAM is not cancelled.

What did you see instead?

In the browser console:
SCRIPT7002: XMLHttpRequest: Network Error 0x2eff, Could not complete the operation due to error 00002eff.
And Edge is waiting after the post response.

On the server with GODEBUG=http2debug=2

2017/04/12 14:46:19 http2: Framer 0xc0420572b0: read HEADERS flags=END_HEADERS stream=7 len=50
2017/04/12 14:46:19 http2: decoded hpack field header field ":method" = "POST"
2017/04/12 14:46:19 http2: decoded hpack field header field ":path" = "/api/note"
2017/04/12 14:46:19 http2: decoded hpack field header field ":authority" = "mysite.com"
2017/04/12 14:46:19 http2: decoded hpack field header field ":scheme" = "https"
2017/04/12 14:46:19 http2: decoded hpack field header field "accept" = "application/json, text/plain, */*"
2017/04/12 14:46:19 http2: decoded hpack field header field "content-type" = "application/json;charset=utf-8"
2017/04/12 14:46:19 http2: decoded hpack field header field "authorization" = "Bearer eyJhbGciOiJIUzI1NiIsInR..."
2017/04/12 14:46:19 http2: decoded hpack field header field "accept-language" = "en-US,en;q=0.5"
2017/04/12 14:46:19 http2: decoded hpack field header field "accept-encoding" = "gzip, deflate"
2017/04/12 14:46:19 http2: decoded hpack field header field "user-agent" = "Mozilla/5.0 (Windows NT 10.0; WOW64; Trident/7.0; rv:11.0) like Gecko"
2017/04/12 14:46:19 http2: decoded hpack field header field "content-length" = "176"
2017/04/12 14:46:19 http2: decoded hpack field header field "cache-control" = "no-cache"
2017/04/12 14:46:19 http2: decoded hpack field header field "cookie" = "io=nqxN0QU2luvbe-XFAAAG; _ga=GA1.1.295991729.1491942281; _gat=1"
echo: http2: server read frame HEADERS flags=END_HEADERS stream=7 len=50
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: read DATA stream=7 len=176 data="{\"project_id\":\"58ee435a835657196c79d252\"}" (49 bytes omitted)
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote WINDOW_UPDATE len=4 (conn) incr=176
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote WINDOW_UPDATE stream=7 len=4 incr=176
2017/04/12 14:46:20 http2: server encoding header ":status" = "200"
2017/04/12 14:46:20 http2: server encoding header "content-type" = "application/json; charset=UTF-8"
2017/04/12 14:46:20 http2: server encoding header "content-length" = "295"
2017/04/12 14:46:20 http2: server encoding header "date" = "Wed, 12 Apr 2017 18:46:20 GMT"
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote HEADERS flags=END_HEADERS stream=7 len=55
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote DATA flags=END_STREAM stream=7 len=295 data="{\"_id\":\"58ee75fc835657337c5aa132\"}" (39 bytes omitted)
2017/04/12 14:46:20 http2: Framer 0xc0420572b0: wrote RST_STREAM stream=7 len=4 ErrCode=CANCEL
@bradfitz bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 12, 2017
@bradfitz bradfitz added this to the Go1.9Maybe milestone Apr 12, 2017
@bradfitz
Copy link
Contributor

Start a golang (1.6-1.8) server with http2 enabled and a valid tls certificate

Can you clarify which exact version of Go you're using? The http2 code has changed over time.

@bradfitz
Copy link
Contributor

In any case, this seems like a bug in Edge.

Logs says:

  • Edge: "Content-length: 176"
  • Edge: DATA stream=7 len=176 data="{"project_id..." (but notably, no END_STREAM)
  • Go runs your handler
  • Go: wrote HEADERS flags=END_HEADERS stream=7 len=55
  • Go: wrote DATA flags=END_STREAM stream=7 len=295 data="{"_id":"58ee75fc835657337c5aa132"}" (39 bytes omitted)

At this point, the client (Edge) has sent all its declared data, but not closed the stream. In theory it could still send Trailers if it wanted to.

Go's handler runs, reads all the body data, and sends its response.

Your Handler (ServeHTTP) now exits, and Go knows you're never going to read any Trailers now, so Go sends a RST_STREAM (ErrCode == Cancel) to Edge, letting the client know the Server's gone away.

Now Edge gets confused, and doesn't even process the completed response HEADERS + DATA w/ END_STREAM we sent?

@hexadecy
Copy link
Author

Current debug output is with the released Go 1.8.1.
I started investigating this since 1.6.

@hexadecy
Copy link
Author

I'm comparing with chrome, you are right.
Chrome:

2017/04/12 13:13:09 http2: server read frame HEADERS flags=END_HEADERS|PRIORITY stream=1137 len=40
2017/04/12 13:13:09 http2: Framer 0xc0423ecdd0: read DATA flags=END_STREAM stream=1137 len=176 data="{\"meeting_id\":\"58ee435a835657196c79d252\",\"proje
ct_id\":\"58a4c2378356572a646f6f53\",\"oftype\":0,\"level\":1,\"title\":\"\",\"content\":\"\",\"pos\":\"17\",\"timestamp\":\"2017-04-12T17:13:09.526Z\"}"

2017/04/12 13:13:09 http2: server read frame DATA flags=END_STREAM stream=1137 len=176 data="{\"meeting_id\":\"58ee435a835657196c79d252\",\"project_id\":
\"58a4c2378356572a646f6f53\",\"oftype\":0,\"level\":1,\"title\":\"\",\"content\":\"\",\"pos\":\"17\",\"timestamp\":\"2017-04-12T17:13:09.526Z\"}"
2017/04/12 13:13:09 http2: Framer 0xc0423ecdd0: wrote WINDOW_UPDATE len=4 (conn) incr=176
2017-04-12T13:13:09-04:00 200 192.168.56.1 POST/api/notebook 1.501ms

Edge:

2017/04/12 13:10:06 http2: server read frame HEADERS flags=END_HEADERS stream=313 len=14
2017/04/12 13:10:07 http2: Framer 0xc04204d930: read DATA stream=313 len=176 data="{\"meeting_id\":\"58ee435a835657196c79d252\",\"project_id\":\"58a4c237
8356572a646f6f53\",\"oftype\":0,\"level\":1,\"title\":\"\",\"content\":\"\",\"pos\":\"16\",\"timestamp\":\"2017-04-12T17:10:06.365Z\"}"
2017/04/12 13:10:07 http2: server read frame DATA stream=313 len=176 data="{\"meeting_id\":\"58ee435a835657196c79d252\",\"project_id\":\"58a4c2378356572a
646f6f53\",\"oftype\":0,\"level\":1,\"title\":\"\",\"content\":\"\",\"pos\":\"16\",\"timestamp\":\"2017-04-12T17:10:06.365Z\"}"
2017/04/12 13:10:07 http2: Framer 0xc04204d930: wrote WINDOW_UPDATE len=4 (conn) incr=176
2017/04/12 13:10:07 http2: Framer 0xc04204d930: wrote WINDOW_UPDATE stream=313 len=4 incr=176
2017-04-12T13:10:07-04:00 200 fe80::ec65:8ecf:bb58:3f4c%Ethernet POST/api/notebook 822.5888ms

@tombergan
Copy link
Contributor

I agree with Brad, this looks like a bug in Edge, so I'm closing this.

@tombergan
Copy link
Contributor

/cc @MikeBishop

@bradfitz
Copy link
Contributor

bradfitz commented Apr 12, 2017 •
edited
Loading

@tombergan, we should probably escalate to the Edge team, though. (Update: you replied at the same time I did :))

We could also consider working around this. Maybe we don't send the cancel for a couple seconds?

@tombergan
Copy link
Contributor

I think @MikeBishop is the Edge contact for HTTP/2.

I'm not sure it's worth delaying the cancel. The client should receive the full response (up to END_STREAM) before receiving the RST_STREAM and could in theory send that response up to the XHR layer.

Do we know what Apache does in this case? Do they leave the stream open indefinitely?

@tombergan tombergan reopened this Apr 12, 2017
@bradfitz
Copy link
Contributor

/cc @icing for the Apache question.

@bradfitz
Copy link
Contributor

bradfitz commented Apr 12, 2017 •
edited
Loading

Stefan, if Edge sends a request with a Content-Length and all the DATA, but no END_STREAM bit ever, and then you finish processing the request & finish sending the response, what does Apache do? Go sends a RST_STREAM with err code CANCEL after our (Go's) END_STREAM. But Edge doesn't like that.

@MikeBishop
Copy link

MikeBishop commented Apr 12, 2017 via email

@tombergan
Copy link
Contributor

@hexadecy, can you provide a repro for @MikeBishop?

On the server side, this appears to be a special case of an early response, in which case the error code should be NO_ERROR rather than CANCEL, shouldn’t it?

Both seem reasonable by my reading. NO_ERROR is "not the result of an error" and "might ... indicate graceful shutdown". CANCEL indicates that "the stream is no longer needed".
http://httpwg.org/specs/rfc7540.html#ErrorCodes

Is there some part of the spec which says that NO_ERROR should be used to close a stream after sending an early response?

@MikeBishop
Copy link

MikeBishop commented Apr 13, 2017 via email

@bradfitz
Copy link
Contributor

@MikeBishop, thanks! Sounds like we should change to NO_ERROR, then:

When this is true, a server MAY
request that the client abort transmission of a request without error
by sending a RST_STREAM with an error code of NO_ERROR after sending
a complete response (i.e., a frame with the END_STREAM flag).
Clients MUST NOT discard responses as a result of receiving such a
RST_STREAM, though clients can always discard responses at their
discretion for other reasons.

@icing
Copy link

icing commented Apr 13, 2017

Just added a test for this. Apache is happy when the content is provided by the client as announced. The request is then served, the response is sent and the stream is closed. I have not tested with a trailer announcement and such, but overall this seems to work.

This is however more an artefact of the HTTP/1.1 request handling than intentional design of the 2 implementation, I must say.

@bradfitz
Copy link
Contributor

@icing, but do you keep any state around for the client, since they've never sent END_STREAM? Or does Edge eventually send it?

@icing
Copy link

icing commented Apr 13, 2017

@bradfitz The server has closed down the processing, but the stream is still hanging around and timeouts do not trigger for it any longer. So, this needs to be fixed as it will otherwise block resources. RST_STREAM with NO_ERROR is probably the way to go here.

No idea if Edge does send it eventually. A GOAWAY will tear it all down properly in the end.

@gopherbot
Copy link
Contributor

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

gopherbot pushed a commit to golang/net that referenced this issue Apr 13, 2017
@tombergan @bradfitz
http2: Use NO_ERROR instead of CANCEL when responding before the requ…
5602c73 
…est is finished

This is required by RFC 7540 Section 8.1.
Bug pointed out by Mike Bishop.

Updates golang/go#19948

Change-Id: I58d4f499609fd493d33115f4e1f64caf4bcbbc03
Reviewed-on: https://go-review.googlesource.com/40630
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@MikeBishop
Copy link

Potential difference from Chrome: Our stream will end with a separate, zero-length payload DATA frame with END_STREAM set. Any chance you're discarding empty frames before looking at the flags?

If not, it would be good to get traces for the client's view. netsh trace start InternetClient_dbg, repro, netsh trace stop and share the resulting .cab file. (Or e-mail to me at michbish@microsoft.com, if you prefer.)

@bradfitz
Copy link
Contributor

Any chance you're discarding empty frames before looking at the flags?

@MikeBishop, I just double-checked: we don't bail out early on zero length. It still processes flags.

@icing
Copy link

icing commented Apr 13, 2017 via email

@hexadecy
Copy link
Author

hexadecy commented Apr 14, 2017 •
edited
Loading

netsh trace was sent @MikeBishop.
Client was Microsoft Edge 38.14393.1066.0 /Microsoft EdgeHTML 14.14393 on Microsoft Windows [version 10.0.14393]
Server was AWS Canada EC2 + CoreOS 1298.7.0 (Ladybug) + Docker version 1.12.6 + Alpine Linux 3.5

@hexadecy
Copy link
Author

hexadecy commented Apr 14, 2017 •
edited
Loading

I think I know why it wasn't reported before.
Hosted, it happens less often than in local.
There is almost no proxy between me and our cloud provider.
Also, if I add this in the handler, I have to call POST many times fast to trigger the error.

d, _ := time.ParseDuration("10ms")
time.Sleep(d)

Now Edge have the time to send the END_STREAM flag.

2017/04/14 12:24:38 http2: Framer 0xc042226000: read HEADERS flags=END_HEADERS stream=295 len=14
2017/04/14 12:24:38 http2: decoded hpack field header field ":method" = "POST"
2017/04/14 12:24:38 http2: decoded hpack field header field ":path" = "/api/notebook"
2017/04/14 12:24:38 http2: decoded hpack field header field ":authority" = "xyz.mysite.io"
2017/04/14 12:24:38 http2: decoded hpack field header field ":scheme" = "https"
2017/04/14 12:24:38 http2: decoded hpack field header field "accept" = "application/json, text/plain, */*"
2017/04/14 12:24:38 http2: decoded hpack field header field "content-type" = "application/json;charset=utf-8"
2017/04/14 12:24:38 http2: decoded hpack field header field "authorization" = "Bearer eyJhbGciOiJIUCI6IkpXVCJ9.eyJBQ0MiOjQ5RtaW5Adm94bG9nLmNhIiwiRVhQIjoxNDk0Nz
c3OTU2LCJJRCI6IjU2MzI2NWI4ODM1NjU3MTM"
2017/04/14 12:24:38 http2: decoded hpack field header field "referer" = "https://xyz.mysite.io/meeting/58f0e7048356570bcced3b8a"
2017/04/14 12:24:38 http2: decoded hpack field header field "accept-language" = "fr-CA,fr;q=0.5"
2017/04/14 12:24:38 http2: decoded hpack field header field "accept-encoding" = "gzip, deflate"
2017/04/14 12:24:38 http2: decoded hpack field header field "user-agent" = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/1
4.14393"
2017/04/14 12:24:38 http2: decoded hpack field header field "content-length" = "176"
2017/04/14 12:24:38 http2: decoded hpack field header field "cache-control" = "no-cache"
2017/04/14 12:24:38 http2: decoded hpack field header field "cookie" = "_ga=GA1.1.2088640870.1492185945; io=z2dv86fy-nyIeSlYAAAB"
2017/04/14 12:24:38 http2: server read frame HEADERS flags=END_HEADERS stream=295 len=14
2017/04/14 12:24:39 http2: Framer 0xc042226000: read DATA stream=295 len=176 data="{\"meeting_id\":\"58f0e7048356570bcced3b8a\",\"project_id\":\"58a4c2378356572a646f6f53\",\"oftype\":0,\"level\":1,
\"title\":\"\",\"content\":\"\",\"pos\":\"30\",\"timestamp\":\"2017-04-14T16:24:38.482Z\"}"
2017/04/14 12:24:39 http2: server read frame DATA stream=295 len=176 data="{\"meeting_id\":\"58f0e7048356570bcced3b8a\",\"project_id\":\"58a4c2378356572a646f6f53\",\"oftype\":0,\"level\":1,\"title\
":\"\",\"content\":\"\",\"pos\":\"30\",\"timestamp\":\"2017-04-14T16:24:38.482Z\"}"
2017/04/14 12:24:39 http2: Framer 0xc042226000: wrote WINDOW_UPDATE len=4 (conn) incr=176
2017/04/14 12:24:39 http2: Framer 0xc042226000: wrote WINDOW_UPDATE stream=295 len=4 incr=176
Yes the END_STREAM!   2017/04/14 12:24:39 http2: Framer 0xc042226000: read DATA flags=END_STREAM stream=295 len=0 data=""
2017/04/14 12:24:39 http2: server read frame DATA flags=END_STREAM stream=295 len=0 data=""
2017/04/14 12:24:39 http2: server encoding header ":status" = "200"
2017/04/14 12:24:39 http2: server encoding header "access-control-allow-origin" = "*"
2017/04/14 12:24:39 http2: server encoding header "cache-control" = "max-age=0, no-cache, no-store, must-revalidate"
2017/04/14 12:24:39 http2: server encoding header "content-encoding" = "gzip"
2017/04/14 12:24:39 http2: server encoding header "content-type" = "application/json; charset=UTF-8"
2017/04/14 12:24:39 http2: server encoding header "expires" = "-1"
2017/04/14 12:24:39 http2: server encoding header "pragma" = "no-cache"
2017/04/14 12:24:39 http2: server encoding header "strict-transport-security" = "max-age=31536000; includeSubdomains"
2017/04/14 12:24:39 http2: server encoding header "vary" = "Origin"
2017/04/14 12:24:39 http2: server encoding header "vary" = "Accept-Encoding"
2017/04/14 12:24:39 http2: server encoding header "x-api-version" = "1.1.0"
2017/04/14 12:24:39 http2: server encoding header "x-content-type-options" = "nosniff"
2017/04/14 12:24:39 http2: server encoding header "x-frame-options" = "SAMEORIGIN"
2017/04/14 12:24:39 http2: server encoding header "x-xss-protection" = "1; mode=block"
2017/04/14 12:24:39 http2: server encoding header "content-length" = "222"
2017/04/14 12:24:39 http2: server encoding header "date" = "Fri, 14 Apr 2017 16:24:39 GMT"
2017/04/14 12:24:39 http2: Framer 0xc042226000: wrote HEADERS flags=END_HEADERS stream=295 len=41
2017/04/14 12:24:39 http2: Framer 0xc042226000: wrote DATA flags=END_STREAM stream=295 len=222 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\xffD\x8d\xcdJ\x041\x10\x84ߥ\xceY\xe9\xfc\xc7<Ǟ\xbcH&\xe9,+\x9
9\x1ff\xa2\"\xe2\xbbKv]\x84:4\xcdW_}\xe3\xf5Z\x10aC\xa5\xea\xb3\x0f\xda:\xeb\xd5\xc4YQ\xb5\xa4!\xb0\xee\x97?\xc6i\xe5\xec\x14\x9c6\xda\u061c\x9e\xf5$s\U00043659\xfbu\xb9\xfc\xbbؓ\xb9\xbbhʙ\x8b\x9eB
\x82\xc0\xb6\xafo\x9c\xfb\x83K&+\xfd\xd8Lθ\xea\xaa\x1d\xbem=\x10\xa1i\xcc\xd7\xfe\xb51\"\t4\xfe\xe0\x86(\x05\xfa\xb57F\x04\xc69\xf3\xd1Ӽ!B\x91\xf4'2'i\xce\xd2Ee\xa2\x0eO&\xa8\x17\b\xf0RJ\xea\xa3CD\
xf2t˙(\xde2\x80\xf5s\xe1\x1dqyoM\xa0p\xe3K\xea|\xdc\x1f?\xbf\x01\x00\x00\xff\xff\xcf.U\x17'\x01\x00\x00"

To be local with Edge, you need a local domain (like active directory) + install a valid CA and run this line:
CheckNetIsolation LoopbackExempt -a -n="Microsoft.MicrosoftEdge_8wekyb3d8bbwe"

@gopherbot
Copy link
Contributor

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

gopherbot pushed a commit that referenced this issue Apr 25, 2017
@bradfitz
net/http: update bundled x/net/http2
0d3143e 
This updates the bundled http2 package from git rev
5602c733f70afc6dcec6766be0d5034d4c4f14de of the x/net repo for:

  http2: Use NO_ERROR instead of CANCEL when responding before the request is finished
  https://golang.org/cl/40630

  http2: enforce write deadline per stream
  https://golang.org/cl/34727

Updates #19948
Fixes #18437

Change-Id: I14500476e91551fa8f27a1aeb8ae3cac9600b74c
Reviewed-on: https://go-review.googlesource.com/41753
Reviewed-by: Kale Blankenship <kale@lemnisys.com>
Reviewed-by: Tom Bergan <tombergan@google.com>
Run-TryBot: Kale Blankenship <kale@lemnisys.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@tombergan
Copy link
Contributor

The Go side of this bug was fixed by the above change.

c3mb0 pushed a commit to c3mb0/net that referenced this issue Apr 2, 2018
@tombergan @bradfitz
http2: Use NO_ERROR instead of CANCEL when responding before the requ…
2471e30 
…est is finished

This is required by RFC 7540 Section 8.1.
Bug pointed out by Mike Bishop.

Updates golang/go#19948

Change-Id: I58d4f499609fd493d33115f4e1f64caf4bcbbc03
Reviewed-on: https://go-review.googlesource.com/40630
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@golang golang locked and limited conversation to collaborators Jun 26, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.9Maybe
Development

No branches or pull requests
6 participants
@bradfitz @icing @MikeBishop @gopherbot @hexadecy @tombergan