Closed Bug 1151939 Opened 11 years ago Closed 9 years ago

Loop sessions ending unexpectedly

Categories

(Hello (Loop) :: Client, defect, P3)

Product:
Hello (Loop)
Component:
Client
Type:
defect
Points:
3

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: abr, Unassigned)

References

Details

(Whiteboard: [quality][investigation])

We're hearing several informal reports of people's room sessions terminating without either party taking action to end the session. We managed to capture some information about a specific instance. Based on conversations with both participants, the experience was: - On the desktop client side, the participant got a "something went wrong" indication. - On the standalone client side, the participant received a "You're the only one in this room" indication. The desktop client user was able to re-join the room nearly immediately, and the session was resumed with no issue. On a close examination of the logs, the issue appears to arise from the client responding in an ungraceful fashion to a HAWK token expiry mid-session (sending a refresh, getting a 410 error with errno=111). Here is a ladder diagram of the session in question: Owner Loop Server Guest | | | |16:26:48.356 join | | |---------------------->| | |200 | | |<----------------------| | | |16:27:09.923 join | | |<----------------------| | |200 | | |---------------------->| | |16:27:10.088 get | | |<----------------------| | |200 | | |---------------------->| |16:31:18.596 refresh | | |---------------------->| | |200 | | |<----------------------| | | |16:31:40.516 refresh | | |<----------------------| | |200 | | |---------------------->| | |16:36:10.940 refresh | | |<----------------------| | |200 | | |---------------------->| |16:36:18.911 refresh | | |---------------------->| | |410 errno=expired | | |<----------------------| | |16:36:19.011 leave | | |---------------------->| | |204 | | |<----------------------| | | |16:36:32.295 leave | | |<----------------------| | |204 | | |---------------------->| | | | | | | Doing a Kibana search for "path:rooms AND action:refresh AND errno:111" and comparing it on a date-for-date basis against the "Number of rooms with occurrences of two peers in a room" numbers on the "Room Funnel" graph for the Loop Server Dashboard shows that this specific kind of interruption is consistently happening to approximately 2% - 2.5% of all room sessions. Rather than ending the session on a recoverable error, the client should re-try the operation and keep the session alive.
If you're working on this and need more information about the network-perceived behavior here, let me know. I can correlate this specific session to Loop-server logs and to the TokBox glasswing logs.
Tagging Shell and Gavin for pull and prioritization. Given the nature and frequency of this defect, I think it warrants an urgent response.
Flags: needinfo?(sescalante)
Flags: needinfo?(gavin.sharp)
After further digging (Mark discovered this), it appears that the 111 response is not due to HAWK token expiration; it happens because the server thinks that the user is no longer in the room. The server code in question appears here: https://github.com/mozilla-services/loop-server/blob/master/loop/routes/rooms.js#L452 As the call flow above demonstrates, the failed 'refresh' above arrives milliseconds too late to successfully refresh the session (the timeout is set to 5 minutes). This is curious, as the client code for refreshing the session bakes in a 10% margin of error (i.e., it should refresh after 4m30s): http://mxr.mozilla.org/mozilla-beta/source/browser/components/loop/content/shared/js/activeRoomStore.js#539
As discussed on irc with Adam and Gavin. This appears to be an issue where setTimeout is too unstable over a 5 minute period for what we need. We probably need to do shorter polling and assess the time using the performance counter. There's no other obvious failure causes at the moment, so setTimeout seems to be the best bet.
Points: --- → 3
Note: I'd suggest we fix the setTimeout issue here, and then split out retrying on failure to a separate bug.
(In reply to Mark Banner (:standard8) from comment #5) > Note: I'd suggest we fix the setTimeout issue here, and then split out > retrying on failure to a separate bug. I agree with this approach. Since you've been looking at the network error handling code just recently, could you please open a new bug to investigate and address retry-related behavior? Thanks.
Flags: needinfo?(standard8)
Mark has next steps.
Assignee: nobody → standard8
Iteration: --- → 40.3 - 11 May
Rank: 30
Flags: needinfo?(standard8)
Flags: needinfo?(sescalante)
Flags: needinfo?(gavin.sharp)
Flags: firefox-backlog+
Priority: -- → P3
Whiteboard: [error][investigation]
I've taken a look at the setTimeout and it seemed fairly stable, though that doesn't mean it couldn't get messed up. Alexis: The times in comment 0 are as shown by kibana. Could it be that the requests are delayed due to processing times, so kibana is showing the time the request was processed, rather than the time it was made? I'm only looking for theoretical ideas here at the moment. I can start to dig into the data whilst you look at the 0.17.x releases.
Flags: needinfo?(alexis+bugs)
Interesting thoughts. I'm actually not sure when the logs appear in kibana, if that shows when the request arrived on the server, but when it's being processed, but the latter wouldn't sound too astonishing to me. NI whd here since he might know more.
Flags: needinfo?(alexis+bugs) → needinfo?(whd)
Logs are indexed with the Timestamp of the message, not its processing time (es_index_from_timestamp is true): https://github.com/mozilla-services/puppet-config/blob/master/shared/modules/shared/templates/hekad/elasticsearch.toml.erb#L124 https://hekad.readthedocs.org/en/latest/config/encoders/espayload.html
Flags: needinfo?(whd)
Iteration: 40.3 - 11 May → 40.2 - 27 Apr
A question arose about whether this issue arose was associated with a particular platform more frequently than others. On a quick analysis of the logs, the reported OSes in the general population (sample size = 1000) are: Android: 1.3% Linux: 8.4% Macintosh: 7% Unknown: 0.6% Windows: 82.7% Looking specifically for this error, we see it arising with a distribution like this: FirefoxOS: 0.6% Linux: 1.3% Macintosh: 7.6% Unknown: 0.3% Windows: 90.2% On a quick glance through these numbers, what stands out is that this issue appears to arise on Windows and Mac more frequently than it does for Linux/Android.
This is probably more illustrative of the issue (again, sample size = 1000): Guest (standalone): 0.6% Owner (desktop): 99.4% So the problem arises much, much more frequently for the owner of a room than it does for a guest.
Iteration: 40.2 - 27 Apr → 40.3 - 11 May
(In reply to (Out of office through 5/1) Adam Roach [:abr] from comment #12) > This is probably more illustrative of the issue (again, sample size = 1000): > > Guest (standalone): 0.6% > Owner (desktop): 99.4% > > So the problem arises much, much more frequently for the owner of a room > than it does for a guest. Some of this higher-on desktop could be due to bug 1160071, we're getting the same error code if you delete a room whilst its open. In the sample, were you always checking the time differences, or just looking for the error code?
Iteration: 40.3 - 11 May → 41.1 - May 25
Whiteboard: [error][investigation] → [quality][investigation]
Depends on: 1164446
Iteration: 41.1 - May 25 → 41.2 - Jun 8
Iteration: 41.2 - Jun 8 → 41.3 - Jun 29
Iteration: 41.3 - Jun 29 → 42.1 - Jul 13
Iteration: 42.1 - Jul 13 → 42.2 - Jul 27
Iteration: 42.2 - Jul 27 → 42.3 - Aug 10
Iteration: 42.3 - Aug 10 → ---
Assignee: standard8 → nobody
Support for Hello/Loop has been discontinued. https://support.mozilla.org/kb/hello-status Hence closing the old bugs. Thank you for your support.
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.