1256244 - V1.0 regression - too many UNEXPECTED_SERVER_RESPONSE (2001) exceptions seen desktop client side

Status: RESOLVED WONTFIX

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

Comment 1

[Romain Testard [:RT]]

Can you please clarify at which point in the flow the exception occurs and if user experience gets affected to help set a priority for this?

Comment 2

[Mark Banner (:standard8)]

Ok, I've dug into the logs. I took a random sampling of about 100 exception reports (some of these were from the same rooms/duplicates, so it was probably around 50 distinct reports, maybe less).

For numbers referenced below:

- 2001 = unexpected server response
- 1013 = peer-to-peer connection failed

From this, I can see that:

- The 2001 exceptions on the link clicker side, only seem to occur after a 1013. I think this has been ongoing for a while.

- The 2001 exceptions on the link generator side, occur in one of two distinct occasions:

a) The link generator is the only person in the room. At some stage the 2001 exception occurs, OpenTok sees this as a publishing failure.

b) There have been two people in the room. The link clicker exits the room, and so the link generator sees the clicker's session being destroyed, and for some reason, this then triggers the 2001.

Since a) wouldn't affect the graphs, I suspect b) is most likely here. As far as I can tell there's no degradation in user experience - it seems that the sdk automatically re-publishes.

Erik, are we able to filter out exceptions after the first person has left the room (if we aren't doing this already)? If so, does that improve the statistics?

Comment 3

[Mark Banner (:standard8)]

Also, need-info to Mike to make him aware of this - Mike, I'll seen you additional info in email direct.

Comment 4

[Erik Rose [:erik][:erikrose]]

Mark, when a person leaves a room, the session ends; that's how I've defined sessions for metrics purposes. So, the only exception that could be construed as post-leave would occur as part of the leave event itself. If I understand (b) correctly, those shouldn't concern us.

That said, the event after a leave would begin a new session, as long as 2 people meet again in the room at some point, so it's possible this later session has your (b) exception right off the bat.

Comment 5

[Erik Rose [:erik][:erikrose]]

HOWEVER, those later sessions would not be reported as part of the exception stats I generated for this bug, unless those sessions themselves never got all the way to Success. I suspect that tamps them down past the point of diminishing returns.

Comment 6

[Ian Bicking (:ianbicking)]

Attachment: Screenshot of browser console

I got some exceptions related to this in the console (screenshot attached), and it put me into the situation where video is lost, audio stays on, and the invitation screen comes up.

Comment 7

[Mark Banner (:standard8)]

I've been able to do some debugging around this, and I've found what appears to be the main issue:

- On the link clicker, when a room transitions to "SESSION_CONNECTED" (i.e. connected to Tokbox's servers) from any other state, it attempts to start browser sharing.

- The browser sharing process will add a new listener to the privileged chrome process to get the tab information, and it sets the tab sharing into a pending state. When the listener is added, there's an initial response that we use to start browser sharing with the appropriate window id. This window id gets passed to the Tokbox SDK with a publish request.

- To get to the SESSION_CONNECTED state, there's currently two ways:

1) When the link generator opens the room, they transition through gathering, joining (and more) to SESSION_CONNECTED.

2) When a link clicker is in the room at the same time as the link generator, the room state will be HAS_PARTICIPANTS, but then, when the clicker leaves the room, the room state reverts to SESSION_CONNECTED.

- Its the latter case that is the issue. Reverting to the fact the session is connected, triggers another start browser sharing request, and another listener is added. At this time, the Tokbox sdk complains:

OT.Publisher State Change Failed:  'PublishingToSession' cannot transition to 'PublishingToSession'sdk.js:32172:5
OT.exception :: title: Unexpected Server Response (2001) msg: undefined
2001 Session.publish :: Unexpected server response. Try this operation again later.
2001 Session.publish :: Session.publish :: Unexpected server response. Try this operation again later.

- When the link clicker joins again (without the link generator having closed the room), everything works, but the SDK appears to be setting up multiple peer connections/streams i.e. one for the tab sharing, plus one for each time the link clicker has exited the room.

Comment 8

[Mark Banner (:standard8)]

From the statistics perspective, I've discussed with Erik how the graph is assessing the furthest state for sendrecv versus success. Here's an outline of our logs in these error cases:

- Generator join 
- Clicker join ***
- Clicker leaves
- Other status messages from generator +++
- <2001 exception from generator>
- Clicker joins again ***

The *** represents where we would expect to classify a session of two people in the room to start from. However, the stats code is actually starting the second session from +++.

So, for the cases where a room has more than one session, we're seeing any session after the first one being reported as having an exception, leading to the reduced success rates of our graphs.

We should fix the stats, but it probably wouldn't revert us to our normal rates until we fix the issue, as I've seen cases where the 2001 comes in after the next clicker join.

Comment 9

[GitHub Autolander Bot]

Attachment: [loop] Standard8:bug-1257009-2001 > mozilla:master

Comment 10

[Mark Banner (:standard8)]

Summary time:

- There's an issue in our code which tries to restart tab sharing, this may cause extra connections/higher load, but doesn't seem to functionally affect things. I've moved this fix our to bug 1257009.

- The stats code is miss-reporting failures outside of the session.

- The Tokbox code appears to detect a duplicate publish, but then allows it anyway. Maybe that's intentional, but I think the errors shouldn't be presented if that's the case.

I'm going to leave the needinfo to Mike to see if there's an SDK issue here.

Comment 11

[Romain Testard [:RT]]

Thanks Mark, lowering the priority now since given the analysis it does not seem like a must fix for 1.2

Comment 12

[Erik Rose [:erik][:erikrose]]

Just chatted with Mark again. To clarify https://bugzilla.mozilla.org/show_bug.cgi?id=1256244#c8 about the stats:

* A stats "session segment" is not a "session of 2 people"; it's just a way of dividing up the stream of events in a room into chunks over which we can establish furthest states.
* Starting a session segment at +++ is expected, as specced at https://github.com/erikrose/hello_stats/blob/b42e0c265c63fc30b7bfed6c4299a8fe1e135433/hello_stats/sessions.py#L271-L272. However, we should not allow states or exceptions to figure in the stats until a second participant joins. We could either move the boundaries of session segments or ignore those states or exceptions. In any case, those events between +++ and *** are needed to establish that the generator is still in the room.

Comment 13

[msander]

Adam, could you take a look at this and see if there is something we'd like to change in the SDK to handle this case better?

Comment 14

[Adam Ullman]

Sure, I have filed a ticket internally for us and we'll investigate it.

Comment 15

[Mark Banner (:standard8)]

This is probably already fixed, but we need to watch it as 1.2 goes out next week.

Comment 16

[Mark Banner (:standard8)]

So bug 1257009 has now been released. We've seen a very small improvement (probably 3%) in the calls complete successfully case.

However, we're still seeing about 20% of conversations not completing successfully after two people have connected to the room.

My local analysis over a week shows that in about 65% of these cases, we're seeing a 1013 (P2P connection failed) error being logged, there's another 30% of cases where we're seeing 2001s (unexpected server response).

Since these all started around FF 45, our best guess is that it is something to do with having turned on screen sharing by default.

Unfortunately our stats don't tell us which connection is failing.

Tokbox is currently looking into the errors as well.

Comment 17

[Mark Banner (:standard8)]

As of Wednesday 13th July, bug 1285916 has been deployed to the standalone. It appears to be reducing the rate that we were seeing some of these exceptions. We're still waiting on more data though.

Comment 18

[Mark Banner (:standard8)]

Short summary of investigations:

- 2001 is a generic error returned by Tokbox when a client calls to the server to do something. This seems to happen in a lot of failure cases (e.g. connection failure) and is coupled with other exceptions.
- The connection rates we were seeing on the graphs were also masked by other stats issues.
- We found a small percentage of issues (~ < 5%) that looked to be a Tokbox issue on their server, and have been reported to Tokbox.
- Most of the rest of issues we would have needed more detailed metrics, which we weren't able to get due to Loop being shut down.

Hence closing this bug as no more to do now.