Crash on ICE renegotiation in race condition

[agclark27]

We've observed occasional crashes that occur on ICE renegotiation in the current master when, possibly, the connection and resources are simultaneously being cleaned up. The crash is occurring at 844/845 in sdp.c:

janus-gateway/sdp.c

Line 844 in d324ac4

c->username = g_strdup(stream->ruser);

AddressSanitizer output is here: https://pastebin.com/NjebVMsH

Your insights would be much appreciated.

[agclark27]

Just for clarification, we're seeing this occurring specifically with ICE restarts.

[agclark27]

One more bit of context, in case it's helpful.

We're initiating an ICE restart for the publisher when we see an ICE state of "failed" or "disconnected", calling the following:

    room.createOffer({
      iceRestart: true,
      media: { audioRecv: false, videoRecv: false, audioSend: false, videoSend: false },
      success: function(jsep)
      {
        room.send({
          'message': { 'request': 'configure' },
          'jsep': jsep,

For subscribers, if we get a disconnected/failed state on their ICE, we call:

              remoteFeed.send({
                message: { request: 'configure', restart: true },

Do you see any issues with this approach that might be related?

[tmatth]

Do you see any issues with this approach that might be related?

Even if there are, we should be avoiding this use-after-free crasher here.

[lminiero]

The asan dump doesn't say where the free happened (no line number), you may want to launch Janus with the ASAN_OPTIONS=fast_unwind_on_malloc=0 env variable set to have that info added.

[lminiero]

Now that I think about it, not sure why we're setting the credentials on the NiceCandidate when we add it in janus_sdp_parse_candidate: libnice should already have the credentials from nice_agent_set_remote_credentials, so it shouldn't be needed. I'll check if we can just get rid of that part.

[lminiero]

I got rid of those in the PR above. Since they were the cause of the crash, it may fix the race condition, but please check and let me know (especially that it doesn't introduce regressions).

[agclark27]

We just picked up an attempted double-free on master with the PR #2046 applied. It doesn't seem to be related to that change, unless we're just seeing this now because the earlier crash is being avoided. https://pastebin.com/SyV51nFd

[lminiero]

That dump makes no sense. It's saying the g_free at line 1895 is trying to free something that was already freed at line 1895, so by the same method: this cannot happen, as libnice makes use of a glib loop to call janus_ice_cb_new_selected_pair, and so the method cannot be invoked twice at the same time for the same handle (the two calls would necessarily happen in sequence as they'd be two separate events in the loop).

[tmatth]

That dump makes no sense. It's saying the g_free at line 1895 is trying to free something that was already freed at line 1895, so by the same method: this cannot happen, as libnice makes use of a glib loop to call janus_ice_cb_new_selected_pair, and so the method cannot be invoked twice at the same time for the same handle (the two calls would necessarily happen in sequence as they'd be two separate events in the loop).

Even if the crash is in thead T7650 and the free was in thread 9?

[lminiero]

Mh, actually it looks like one was triggered by the loop (the one that crashes), and the other was actually originated by a janus_process_incoming_request call (parsing a trickle). This seems to suggest not all libnice callbacks are triggered by its event loop, as I thought, which is an issue.

[lminiero]

If janus_ice_cb_new_selected_pair can be triggered by threads other than the one handling the loop, this is an issue, since we cannot use the handle mutex (parsing a trickle locks it already, for instance) to ensure thread safety. I guess the only solution here will be to only call nice_agent_set_remote_candidates from the loop, which means queueing candidates we parsed to have them processed in janus_ice_outgoing_traffic_handle (as we do for some other callbacks we want to always be executed by the loop).

If the same can happen for other callbacks, though, it's very annoying.

[lminiero]

Printing the thread IDs that trigger those callback in a simple EchoTest session, I can confirm that some were not triggered by the loop in my case... specifically:

• janus_ice_cb_candidate_gathering_done was triggered by the thread handling the message with the SDP offer: this definitely happened because it was the thread that called janus_ice_setup_local, which is where nice_agent_gather_candidates is. Since I'm not using STUN or TURN in Janus, but only collect host candidates, when that method returns all candidates are ready.
• janus_ice_cb_component_state_changed was called multiple times, as expected, but not always from the same thread: sometimes it was the loop, other times it was the thread that handled an incoming "trickle" request. In this case, it was definitely the nice_agent_set_remote_candidates call that caused it, as I printed the backtrace in the method to see how we got there.
• In my test, janus_ice_cb_new_selected_pair was always called by the loop, but as we've seen from the crash, nice_agent_set_remote_candidates can cause it to be called by something else too.
• Luckily, janus_ice_cb_nice_recv seemed to always be called by the loop.

That said, it looks like at the very least I should ensure that nice_agent_set_remote_candidates is always called by the loop. I'll merge #2046 (since that seems harmless) and work on a new PR to do that.

[lminiero]

Please test PR above. Not going to touch the code until Monday, so feel free to report issues but I won't look at anything until then.

[lminiero]

@agclark81 @tmatth any feedback on the PR?

[tmatth]

@lminiero I'm still testing it, so far no obvious issues though.

[agclark27]

We deployed the PR to production as of about 12 hours ago, and we just picked up another heap-use-after-free crash, but this one occurred in the videoroom plugin, so it may not be an issue in the PR. https://pastebin.com/Zdnmui3e

[lminiero]

One day you'll have to explain me why you're doing all these renegotiations and restarts... it's that same scenario in the VideoRoom as well 😝
Apparently it's dying when updating a subscription, because the subscription was destroyed. Probably something you're doing wrong on the client side, where you update and close at the same time. That said, something we'll have to look into, but not here: I'd rather we solve one thing at a time, and not mix issues.

[lminiero]

As soon as you guys give me the green light, I'll merge that PR and look in the VideoRoom problem.

[agclark27]

The PR looks good from our perspective, and I think if there was a major issue we would have hit it already. Our volume is pretty high (500+ separate webinars were hosted just yesterday using the videoroom plugin, with one webinar having 600+ attendees and 6 publishing video streams, so 3600+ subscribing feeds), and the ICE restarts are pretty rare, but with that as the denominator, they are still occurring.

We initiate an ICE restart for a publisher when we get a 'failed' or 'disconnected' state using createOffer({ iceRestart: true..., and a configure message with restart: true for a subscriber when the remote feed changes its ICE state to 'failed' or 'disconnected'. If we get an error from the ICE restart, we'll attempt again in 5 seconds, so there may be a condition where the subscribers are trying to restart the remote feeds while the publisher stream gets cleaned up and the subscription is destroyed.t

[lminiero]

If we get an error from the ICE restart, we'll attempt again in 5 seconds, so there may be a condition where the subscribers are trying to restart the remote feeds while the publisher stream gets cleaned up and the subscription is destroyed.t

Makes sense, the user may also be refreshing the browser when the video freezes because of the failed state, which may cause the race condition while you try to recover it.

Thanks for the feedback, I'll merge then. I'll prepare a different PR for the VideoRoom issue when I have a clearer understanding of what needs to be done (on the top of my head, I'd say we need a refcount increase, but we'll see).

[lminiero]

Actually, I think we can keep this issue open, for the VideoRoom thing (since it's still a race condition that happens during renegotiations).

[lminiero]

Tentative fix for the VideoRoom race condition, @agclark81. PS: please let me know if you plan to update #2043 soon: it's blocking #2044. Thanks.

[lminiero]

PS: please let me know if you plan to update #2043 soon: it's blocking #2044. Thanks.

I guess not...

[agclark27]

Things are looking good thus far with refcounting subscribers. We've also made a couple of client-side changes that may help to reduce the likelihood of this race condition, wherein we skip the hangup of the room and the destroy of janus if we have an ICE renegotiation in progress on the client side. We're also now experimenting with only bringing webinar guests in with a ptype of 'subscriber' and sending all media start messages over textroom, which we were already using, and only joining in attendees as publishers to the videoroom if they'll ever be publishing media. I'll let you know if we encounter any further issues here.

[lminiero]

Merged #2061, so I'll close.