WebSocket onclose fired before onMessage when frames are received at almost the same time
Reported by
tim.dawb...@gmail.com,
Mar 22 2016
|
||||||
Issue description
UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.87 Safari/537.36
Steps to reproduce the problem:
1. Send two data frames followed by a close frame, a fraction of a millisecond apart.
2. The onclose event will get triggered before the onmessage event, and the onmessage event will not get called
3. This causes the data frames to be dropped from the client's perspective — no event is ever triggered to receive them
What is the expected behavior?
Data is not lost.
What went wrong?
In the first screenshot is a screenshot of the WebSocket frames. Note that there are three data frames sent right before the WebSocket is closed (~13:49:31.32*). The WebSocket is closed by the server at ~13:49:31.328.
In the second screenshot, I show the output of a `console.log("onmessage", event)` as the `onmessage` and `onclose` callbacks respectively. Note that the final three frames (~13:49:31.32*) aren't triggering an `onmessage`.
Did this work before? Yes As far as I'm aware, this has worked in all prior stable Chrome releases as we would have noticed it before.
Chrome version: 49.0.2623.87 Channel: stable
OS Version: OS X 10.11.3
Flash Version: Shockwave Flash 21.0 r0
This isn't deterministic. It happens about one in every four runs, indicating it's some kind of timing issue.
,
Mar 22 2016
I'm confused because the close code is 3000 in the table but 1005 in the console output. Are you certain that your server is sending a close frame with code = 3000? If you can provide a net-internals log, that would be really helpful. Thanks,
,
Mar 22 2016
Ah, I can see why that might be confusing. That final frame is a data frame, not a control frame. The data frame just happens to contain content that looks like the contents of a control (closing) frame. It's contents is the literal text `c[3000, "Go away!"]`. I've attached a net-internals log from another repro. Let me know if you need anything else.
,
Mar 22 2016
Oh, and the WebSocket URL in that net-internals log is ws://localhost:8080/shell/bash/253/j07lj7r2/websocket
,
Mar 22 2016
I think this is a bug in the WebSocket browser-side implementation. In net::WebSocketChannel::HandleFrameByState, data frames might be buffered, but control frames will be delivered immediately, i.e., overtake data frames.
,
Mar 22 2016
,
Apr 11 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/d2727dfa142f063944cd57e1de9900609ff2ec32 commit d2727dfa142f063944cd57e1de9900609ff2ec32 Author: yhirano <yhirano@chromium.org> Date: Mon Apr 11 05:32:49 2016 [WebSocket] Incoming close frame should not overtake data frames Incoming data frames are throttled by quota maintained by both the browser side and the renderer side websocket implementations. On the other hand, when a CLOSE frame arrives, it is notified immediately to the renderer side. As a result, a CLOSE frame overtakes data frames, which is bad. BUG= 596761 Review URL: https://codereview.chromium.org/1820233002 Cr-Commit-Position: refs/heads/master@{#386337} [modify] https://crrev.com/d2727dfa142f063944cd57e1de9900609ff2ec32/content/browser/renderer_host/websocket_host.cc [modify] https://crrev.com/d2727dfa142f063944cd57e1de9900609ff2ec32/net/websockets/websocket_channel.cc [modify] https://crrev.com/d2727dfa142f063944cd57e1de9900609ff2ec32/net/websockets/websocket_channel.h [modify] https://crrev.com/d2727dfa142f063944cd57e1de9900609ff2ec32/net/websockets/websocket_channel_test.cc
,
Apr 14 2016
tim.dawborn@, could you verify if my fix works as expected with Chrome Canary?
,
May 6 2016
I didn't keep the same test data that I was using initially, but I can't repro the problem anymore, so I guess that's a LGTM.
,
May 9 2016
Thank you for verifying.
,
May 9 2016
|
||||||
►
Sign in to add a comment |
||||||
Comment 1 by tim.dawb...@gmail.com
, Mar 22 2016