[1.x] possibly deadlock in audiobridge

[spscream]

What version of Janus is this happening on?
1.3.2, our branch based on fd24309 commit(audiobridge isn't modified by us)

Have you tested a more recent version of Janus too?
Not yet, but we hit a deadlock condition on one of our customers using the specified version.

Was this working before?
not sure

Is there a gdb or libasan trace of the issue?
Here are gdb logs from two broken servers:
https://gist.github.com/spscream/7dafebd6bb1a39493f838aebf88fba26

Additional context
I looked into the code of ab, in janus_audiobridge_handler:

janus-gateway/src/plugins/janus_audiobridge.c

Line 6557 in fd24309

janus_mutex_lock(&sessions_mutex);

a mutex is locked here.
and in

janus-gateway/src/plugins/janus_audiobridge.c

Line 6677 in fd24309

janus_mutex_lock(&rooms_mutex);

it locks rooms_mutex
So the lock order is: lock sessions_mutex -> lock rooms_mutex -> unlock rooms_mutex-> unlock sessions_mutex

This could possibly lead to a deadlock condition in other places, e.g. here:

janus-gateway/src/plugins/janus_audiobridge.c

Line 2957 in fd24309

janus_mutex_lock(&sessions_mutex);

Here the lock order is: lock sessions_mutex -> unlock sessions_mutex -> lock rooms_mutex -> unlock rooms_mutex

I'm not sure this is exactly our case, but it could potentially lead to such a condition in other places too.

[lminiero]

I'm still out of office, I'll have a look next week.

[spscream]

we had same issue with our server, it based on fff7b31 commit

it looks like it is locked in janus_audiobridge_participant_clear_outbuf on g_async_queue_pop, while holding rooms mutex

here is gist of this hang:
https://gist.github.com/spscream/ca8b82d2063d35e8ca894795f266a3f8

[spscream]

btw also found this lock in previous logs:

Thread 206 (LWP 506437 "pool-janus"):
#0  0x00007f337c8ae158 in __syscall6 (a6=<optimized out>, a5=<optimized out>, a4=<optimized out>, a3=<optimized out>, a2=<optimized out>, a1=<optimized out>, n=<optimized out>) at ./arch/x86
_64/syscall_arch.h:59
#1  syscall (n=<optimized out>) at src/misc/syscall.c:20
#2  0x00007f337c5467c3 in g_cond_wait () from /usr/lib/libglib-2.0.so.0
#3  0x00007f337c4ab6a4 in ?? () from /usr/lib/libglib-2.0.so.0
#4  0x00007f337c4abb68 in g_async_queue_pop () from /usr/lib/libglib-2.0.so.0
#5  0x00007f337b3d3c3e in janus_audiobridge_participant_clear_outbuf (participant=<optimized out>) at plugins/janus_audiobridge.c:1888
#6  janus_audiobridge_process_synchronous_request (session=session@entry=0x7f3370be6d90, message=message@entry=0x7f337691deb0) at plugins/janus_audiobridge.c:3905
#7  0x00007f337b3ec9b0 in janus_audiobridge_handle_message (handle=0x7f336febd520, transaction=0x7f337a325ac0 "YYZmSkeD3Ik", message=message@entry=0x7f337691deb0, jsep=jsep@entry=0x0) at plu
gins/janus_audiobridge.c:6159
#8  0x0000560ae6428731 in janus_process_incoming_request (request=0x7f337691e360) at janus.c:1847
#9  0x0000560ae642f465 in janus_transport_task (data=0x7f337691e360, user_data=<optimized out>) at janus.c:3557
#10 0x00007f337c516103 in ?? () from /usr/lib/libglib-2.0.so.0
#11 0x00007f337c5155f0 in ?? () from /usr/lib/libglib-2.0.so.0
#12 0x00007f337c8d134f in start (p=0x7f33793478e8) at src/thread/pthread_create.c:207
#13 0x00007f337c8d3965 in __clone () at src/thread/x86_64/clone.s:22
Backtrace stopped: frame did not save the PC

[spscream]

@lminiero any updates? we got another stuck today

[lminiero]

I haven't looked at the log yet. I only got back to work yesterday, and I've been busy catching up with a few activities. I'll get to this when I can.

[lminiero]

@spscream any chance you can test with the latest master, or at least the latest tagged version? There have been many commits to the AudioBridge since the commit you're using, some of which have moved the code around quite a lot. There's also a commit involving mutexes, although I don't think that's very relevant (it's mostly on cleanup of mutexes).

As to your overview of the locks, while it does indeed look like both rooms_mutex and sessions_mutex are locked, I don't think it's because of what you wrote:

So the lock order is: lock sessions_mutex -> lock rooms_mutex -> unlock rooms_mutex-> unlock sessions_mutex

This could possibly lead to a deadlock condition in other places, e.g. here:
[..]
Here the lock order is: lock sessions_mutex -> unlock sessions_mutex -> lock rooms_mutex -> unlock rooms_mutex

That second flow doesn't show a reverse order: it shows mutexes being individually locked and then unlocked.

What sounds possibly more likely is something going wrong in that first flow in general, as in that case both locks would be taken and not released. The window of opportunity seems to only be on a "join" request, and only for a brief moment (looking for the room you're joining), as rooms_mutex is quickly released after that, so I don't think something can happen there. If something else got stuck on rooms_mutex before that, though, that would be enough to "lock" both mutexes at the same time.

As such, my guess is that it's a deadlock on rooms_mutex, which then cascades to sessions_mutex as well as soon as the next person joins (even though I don't see anything stuck at lines 5953 and 6392, which are the sessions_mutex locks when handling synchronous and asynchronous messages).

btw also found this lock in previous logs:

That seems to be on yet another commit, as lines don't match neither master nor the commit you gave me. So please, try to replicate with the latest version of the AudioBridge so that I don't go crazy with branches... In general, I do see a janus_audiobridge_participant_clear_outbuf reference in the other gist log too, but the g_async_queue_pop uses an async queue, which has an internal mutex of its own, so from a quick glance I don't see how that could be stuck (especially considering we don't use external mutexes to read/write to it).

[spscream]

g_async_queue_pop could block forever in case no data available in buffer it popping, until new data available

[spscream]

ok, I will check it on version rebased from master, but it hangs randomly, so asap it hungs I'll update issue

[lminiero]

g_async_queue_pop could block forever in case no data available in buffer it popping, until new data available

That shouldn't happen, though, as we have a g_async_queue_length > 0 check before that. But it's a good point that maybe switching to a _try_pop and a NULL check for pkt might help, if that's the case.

Another possibility is that outbuf is no longer a valid queue instance, e.g., because it was freed or its parent was. That's something you may be able to check by inspecting the trace with gdb, and printing the value of outbuf and its participant to see if it makes "sense" (and possibly check if the queue is empty). Compiling with libasan might help as well, if we're accessing an invalid pointer.

[spscream]

got new hang on audiobridge from master:
https://gist.github.com/spscream/6dbce35934d461603d7f9eba739acdeb

[lminiero]

In this new log I only see sessions_mutex being deadlocked, not rooms_mutex. There are a ton of attempts to lock the mutex when hanging up the PC (hangup_media) or closing the handle (destroy_session), I guess depending on which happened first when you had users leave a room. I also see the g_async_queue_pop at line 1888, which we discussed a couple of messages ago: since that's happening in hangup_media_internal, while holding rooms_mutex (which we did mention has a brief overlap with sessions_mutex that I don't see in the log, though) I'll start by implementing the switch to a try_lock to see if that helps.

Actually, when I say that's the only mutex I see deadlocked, that's not entirely true: I see a lock on a room mutex as well, but just a single instance of that,

#3  0x00007d4a9fe9b998 in janus_audiobridge_mixer_thread (data=<optimized out>) at plugins/janus_audiobridge.c:8567

so I don't think that's actually relevant.

I also see a couple of instances where it seems to be waiting on opus_encode, but that may also not be relevant: if the code is stuck on an opus_encode, it means the encoding volatile flag stays set to 1, and that may cause problems when we call hangup_media_internal as we have a busy loop there waiting for the encoder not to be in use while holding sessions_mutex:

	while(!g_atomic_int_compare_and_exchange(&participant->encoding, 0, 1))
		g_usleep(5000);

That said, I don't see any line in your gdb log stuck there, which suggests that's not happening.

Considering we've confirmed that sessions_mutex is the one deadlocked, I'd suggest a couple of things to try: first of I'll push the change to try_lock when cleaning up the buffer, and let you know when the commit is ready, but what may be more helpful is if you add some code to debug the relevant locks. To keep this confined without exploding the logs, I suggest the following changes in the AudioBridge:

1. change all calls to janus_mutex_lock(&sessions_mutex) to janus_mutex_lock_debug(&sessions_mutex)
2. change all calls to janus_mutex_unlock(&sessions_mutex) to janus_mutex_unlock_debug(&sessions_mutex)
3. change all calls to janus_mutex_lock(&rooms_mutex) to janus_mutex_lock_debug(&rooms_mutex)
4. change all calls to janus_mutex_unlock(&rooms_mutex) to janus_mutex_unlock_debug(&rooms_mutex)

That would basically be the same as enabling locking debug, but only for those two mutexes in the AB. Since they're only used for management requests and when people get in and out, their impact on the logs will be very limited (just checked and verified that). This way, should you encounter a deadlock again, all we have to do is check when we stop seeing unlocks to see what specifically caused us to get stuck.

I'll start by committing the try_unlock change, and then you can make those lock_debug changes yourself (which should be as simple as a global replace in the file).