Janus-gateway: WebSocket transport dead lock

[cedricfung]

I'm using Janus video room plugin to develop a new website, and have found this issue for several times. e.g. the WebSocket won't accept any new client after some tests.

After tracing the code execution, I found the code block at

JANUS_LOG(LOG_VERB, "[%s-%p] WebSocket connection accepted\n", log_prefix, wsi);
if(ws_client == NULL) {
    JANUS_LOG(LOG_ERR, "[%s-%p] Invalid WebSocket client instance...\n", log_prefix, wsi);
    return -1;
}
/* Clean the old sessions list, in case this pointer was used before */
janus_mutex_lock(&old_wss_mutex);

I have some old clients exited without cleanup, e.g. no detach handle, etc.

Is this expected to happen when clients don't cleanup resources before disconnect?

[lminiero]

We have an old pointers list in place because the object allocation for the WebSockets client is done by the library itself, and it tends to reuse old pointers for that. Since we use those pointers as opaque identifiers for the transport in place, we have to do some magic, specifically making sure we don't handle send requests from the core on a transport we know has gone (e.g., closed connection, so we added the pointer to the "old list"), and making also sure the "old list" is updated whenever we get a new connection (if a pointer previously used for a connection was in the "old list" and the same one is used for a new connection, remove it from the "old list"). This is indeed a bit wacky, and is not an issue anymore in the reference counters branch for instance as in that case the pointer we use to identify transports is a container we create ourselves.

That said, not sure what can cause that to deadlock. libwebsockets is single threaded and so if it's stuck there it won't indeed go on, but why it locks there is something we'll have to investigate. Probably a lock somewhere else where we don't unlock in some if/then/else branches? I'll have a look.

[lminiero]

PS: if you find it easy enough to replicate, you can try enabling the locking debug in Janus and try again until it happens. This way, you should be able to see exactly where in the code the double locking happens for you.

[cedricfung]

Thanks. I just enabled the lock_debug, and will wait for this to happen again.

BTW: when will the new refcount branch will be considered stable?

[lminiero]

As soon as it is! :wink:
Jokes apart, there are people testing this and we try to do that whenever we can too. If you're interested in giving it a go in some of your application scenarios, it will definitely help move it forward faster!

[cedricfung]

Will try it soon. And I just noticed another issue, if I start a WebSocket connection, close it, then open another connection soon, a timeout message will be sent to the new connection with old session id.

I'm not sure if this is a bug, because I can deal with it in client code.

[lminiero]

Yeah, that's something we experimented too, and happens when a new connection arrives as soon as the previous one ends and the two share the same "pointer". In that case, Janus might be a little to slow to notify the timeout, use the pointer it had, and so the event will get to the new connection instead of the old one. Again, something that with the reference counter branch won't happen.

To solve that issue in the short term, we might simply add a map in the transport, so that we always feed the core with a different pointer no matter what it points to, as it would be mapped to the actual transport structure.

[lminiero]

@vecio any update on the lock debugging?

[cedricfung]

Not occurred any more, have been running the service for one month.

[lminiero]

Ok, closing the issue then. Feel free to reopen should this reappear.

[shrhoads]

I don't have a button to reopen this issue but I am having this issue with the latest master code. It happens about once a day where janus doesn't crash, but it will no longer accept websockets. I'm using the latest libwebsockets. When I build it says using the "new api".

Is there an alternative library I can use to work around this issue?

I'm going to enable lock_debug. Also using the sip plugin only.

BTW in github if a contributor (Iminiero) closes an issue only they can reopen it.

[lminiero]

BTW in github if a contributor (Iminiero) closes an issue only they can reopen it.

@shrhoads didn't know about this, reopening then. If you can provide some lock_debug info or find a way to replicate this it would definitely be helpful. My guess is that the libwebsockets context stops generating events for some reason, e.g., some problem in lws_service. You can set a more verbose logging for WebSockets themselves here, which might give you more info when things stop working.

[lminiero]

As a side note, you can try changing the LOG_HUGE here in something that's included in your debugging level (e.g., LOG_VERB if you're using level 5, or LOG_INFO for level 4). It will spam your logs much more, but again missing events after the lock may confirm the fact that events are not flowing anymore.

[cedricfung]

This issue occurred to me again, will try to get some useful log.

[cedricfung]

Recently I have been using the latest refcount branch, there is no this issue any more.

[zombiecong]

Same issue with the latest master code , I have this issue when I build Janus in Mac, and it works well in ubuntu.

[shrhoads]

It does happen on ubuntu, too, although it hasn't happened again for 1.5 weeks so far.

[shrhoads]

If you can readily reproduce on mac, can you add the logging/etc. suggested above?

[zombiecong]

It happens on Mac every time and every request, I test both old api and new api of libwebsockets. And http transport works well.

@shrhoads This is lock_debug log : https://gist.github.com/zombiecong/e1417c8001b12c8478ed5658d4181d32

I sent a janus "create" request, there was no response from server.After a moment, I saw the session "timeout" log and the session was released.

BTW:I build some dependencies libs by myself , not by homebrew.

[lminiero]

Sorry, missed this notification, apparently... bridging #798 here as well, as it's the same issue (SIP or VideoRoom are not the issue).

[lminiero]

I don't think it's a locking issue in Janus, as you get to the Bye! with no problem, which I believe wouldn't happen if it were stuck somewhere. Maybe a libwebsockets/MacOS specific issue? Try enabling a higher libwebsockets debugging instead to see if it gives any insight: https://github.com/meetecho/janus-gateway/blob/master/conf/janus.transport.websockets.cfg.sample.in#L14

[sslivins]

I am also hitting the deadlock issue, running openssl 1.0.1e, libwebsockets 2.2.0. I tried disabling secure websockets and just used an unsecure websocket with the decryption handled via nginx but still luck. I can repro this issue at least once per day. I will try some more logging in libwebsockets and post an update

[atyenoria]

same issue with the latest refcount branch, libwebsockets 2.2.0, OpenSSL 1.0.1t, debian jessie docker container on ubuntu 16.14. If this happens, creating http request also can't work in addition to websocket request.

[lminiero]

Wait, if HTTP requests fail too, then it is indeed a lock in Janus causing this. Can the others confirm? I was under the assumption that the HTTP API was still working when this happened.

[cedricfung]

I can confirm that the issue is also in the latest refcount branch.

[lminiero]

I won't be able to do any test before the IETF ends. If you guys can find ways to replicate this in the meanwhile, so that I can check for myself when I get back, that would help.

[sslivins]

I was able to reproduce this with libwebsockets logging at the highest level (4095): https://www.dropbox.com/s/3wwqlhp0ksk4e4f/janus_deadlock.log

I have an external process that hits janus over wss on the localhost every minute and this is visible in the log by looking for the message: Message for Session 278: {"id": 0, "request": "watch"}

the first appears at 20:54:32, there should have been another one at 20:55:32 and another at 20:55:32. My watchdog thread kills Janus with an exit status of 99 if it doesn't get a new sessions request for 2 minutes which was the case at 20:54:32

[lminiero]

Can't seem to be able to replicate the issue. Please, if you have an easy way to consistently replicate the issue, then provide the steps here so that I can try and check if it happens to me as well. Logs with the locking debug enabled (either via configuration or via Admin API) when the issue happens will also help me identify which lock is being held and not released, if any.

[lminiero]

Has this been magically fixed for you all? :wink:

[sslivins]

i dont know steps to reproduce but i'll get you some logs with locking logging enabled...shouldnt take long

[shrhoads]

I don't think it's fixed, but I run SIP sessions and video room sessions on separate janus instances and that seemed to stop the deadlocks... Not sure.

[sslivins]

@lminiero here is the first log, i'll likely get more as the day progresses. let me know if additional ones are useful: https://www.dropbox.com/s/oi2le65uyhi40kl/dist1.sea.janus.deadlock.log.zip?dl=0

[lminiero]

@sslivins thx! Is this a log where you restarted due to the WS deadlock?

[sslivins]

if there are no new sessions for 2 minutes i exit(99), so the deadlock is probably back about 2mins or so from the restart which happened around 15:08:50

[lminiero]

Ack, writing a quick'n dirty nodejs application to crawl the log and find out which locks are still held when the log ends: hopefully this can then be used to search where in the log specifically we have locked stuff.

[lminiero]

@sslivins as a side note, which revision are you on? Line numbers don't match.

[sslivins]

i have made a few modifications to janus proper https://github.com/WatchBeam/janus-gateway

[lminiero]

Thanks! I think I found where it blocks for you. I'm sharing the nodejs application I write, just in case it can be of use to anybody else for parsing their own locking debug logs. Just save it to a js file, and pass the path to the logfile to process when executing it.

if(process.argv.length <= 2) {
    console.log("Missing filename...");
    console.log("Usage: " + process.argv[0] + " " + process.argv[1] + " logfile");
    process.exit(1);
}
var filename = process.argv[2];
console.log("Parsing log file " + filename + " for LOCK/UNLOCK evaluation...");

var locks = {};
var lineReader = require('readline').createInterface({
    input: require('fs').createReadStream(filename)
});
lineReader.on('line', function(line) {
    if(line.indexOf("LOCK") < 0)
        return;
    // Found a line: is it a lock or an unlock? what for?
    var unlock = line.indexOf("UNLOCK") > -1;
    var mutex = line.split("LOCK ")[1];
    if(unlock) {
        delete locks[mutex];
    } else {
        var count = locks[mutex] ? locks[mutex].locks : 0;
        locks[mutex] = {
            locks: count+1,
            line: line
        }
    }
});
lineReader.on('close', function() {
    console.log("Locks still taken:");
    console.log(locks);
});

As you see, very dumb, simply goes line by line looking for LOCK/UNLOCK occurrences, and then updates a map with all of them. When an UNLOCK is detected, the lock is removed from the map, otherwise we increase a count, and take note of the last line where a lock was attempted on that item. This can result in a few false positives (e.g., a LOCK appeared for which an UNLOCK happened, but you stopped logging in the meanwhile), but the fact we print the line gives a good indication of where the problem can be.

For your log, it resulted in this output:

[lminiero@lminiero node-janusdemo] $ node lock-parser.js ~/Scaricati/dist1.sea.janus.deadlock.log 
Parsing log file /home/lminiero/Scaricati/dist1.sea.janus.deadlock.log for LOCK/UNLOCK evaluation...
Locks still taken:
{ '0x7fcff00886c8': 
   { locks: 1,
     line: 'Apr 27 15:08:32 dist1.sea01.beam.pro janus[10625]: [ice.c:janus_ice_handle_destroy:1022:] LOCK 0x7fcff00886c8' },
  '0x7fd0800bf678': 
   { locks: 1,
     line: 'Apr 27 15:08:32 dist1.sea01.beam.pro janus[10625]: [ice.c:janus_ice_send_thread:3564:] LOCK 0x7fd0800bf678' } }

From this log, there's 0x7fd0800bf678, which is the component mutex and there related to stuff we do in the ICE send thread, and there's 0x7fcff00886c8, a session mutex. The latter seems more interesting, as following the last line from our results above in the log we can see:

Apr 27 15:08:32 dist1.sea01.beam.pro janus[10625]: [ice.c:janus_ice_handle_find:968:] LOCK 0x7fcff00886c8
Apr 27 15:08:32 dist1.sea01.beam.pro janus[10625]: [ice.c:janus_ice_handle_find:970:] UNLOCK 0x7fcff00886c8
Apr 27 15:08:32 dist1.sea01.beam.pro janus[10625]: [ice.c:janus_ice_handle_destroy:1022:] LOCK 0x7fcff00886c8

which refer to these lines here:

https://github.com/WatchBeam/janus-gateway/blob/impstar/ice.c#L968
https://github.com/WatchBeam/janus-gateway/blob/impstar/ice.c#L970
https://github.com/WatchBeam/janus-gateway/blob/impstar/ice.c#L1022

The last line is from janus_ice_handle_destroy and, considering there's no unlock after that, it makes me think that either in some cases we're returning from the method without unlocking, or something else is locking the method which never returns.

Are you using a single session for all users/handles, by any chance?

[sslivins]

im not sure what you mean by 'a single session for all users/handles'. I not intimately familiar with how janus proper works but my understanding is each ws connection is it's own session, at least that's how my plugin sees the world

[lminiero]

I meant as in a single Janus session handling all handles: in that case, an unreleased lock on the session object would affect other users as well. Anyway, from what you say I don't think that's what's happening. From the log I can see it at least gets to line 1055 (where we logged an unlock), which is followed by a call on the plugin's destroy_session function pointer (your plugin, which is there the Destroy Session request for Session 843 comes from I guess).

After that, we don't know. The unlock is at line 1086 but we never get there, so my guess is that the method never returns. It might either be locked in the destroy_session of your plugin (since it's not available I can't check that), or maybe in the call to g_main_loop_quit. I don't think it's stuck in janus_session_notify_event, as otherwise we'd see the attempts to lock session_mutex in the log, which isn't there.

At any rate, even if janus_ice_handle_destroy is blocked, it shouldn't lock the WebSockets server, as the way we handle requests in the Janus transports, is that we get a request, pass it to the core, and the core spawns a task from a thread pool to handle it: this means that this blocked request shouldn't block the WebSockets handler (which being based on libwebsockets, is single threaded).

[sslivins]

arg...looks like systemd is throttling the logging so this log isnt any good, there are chunks of 30s missing from the logging...let me figure that out and get another capture

[sslivins]

okay, i got a couple more instances with full logging. note the files are very large when uncompressed:

https://www.dropbox.com/s/ohp4z6wfvj1v06d/janus-deadlock.log.bz2?dl=0
https://www.dropbox.com/s/fev5om603s0devz/janus-deadlock2.log.bz2?dl=0
https://www.dropbox.com/s/de4zorpy5y25dep/janus-deadlock3.log.bz2?dl=0

i tried the first one and didnt get anything. i didnt try the second one. the third one returned this:

Parsing log file d:\tmp\janus-deadlock3.log for LOCK/UNLOCK evaluation...
Locks still taken:
{ '0x7f1f907ff620':
   { locks: 7,
     line: '[transports/janus_websockets.c:janus_websockets_common_callback:1032:] LOCK 0x7f1f907ff620' },
  '0x7f1f7c100890':
   { locks: 1,
     line: '[transports/janus_websockets.c:janus_websockets_send_message:849:] LOCK 0x7f1f7c100890' },
  '0x7f1f78017a88':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f78017a88' },
  '0x7f1f7834d528':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f7834d528' },
  '0x7f1f784305d8':
   { locks: 2,
     line: '[ice.c:janus_cleanup_nack_buffer:305:] LOCK 0x7f1f784305d8' },
  '0x7f1f78340cf8':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f78340cf8' },
  '0x67fde0':
   { locks: 41,
     line: '[janus.c:janus_session_notify_event:466:] LOCK 0x67fde0' },
  '0x7f1f783bc168':
   { locks: 2,
     line: '[ice.c:janus_cleanup_nack_buffer:305:] LOCK 0x7f1f783bc168' },
  '0x7f1f783a0098':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f783a0098' },
  '0x7f1f783b6768':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f783b6768' },
  '0x7f1f7828bac8':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f7828bac8' },
  '0x7f1f7825c8a8':
   { locks: 2,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f7825c8a8' },
  '0x7f1f7827c478':
   { locks: 1,
     line: '[ice.c:janus_ice_send_thread:3564:] LOCK 0x7f1f7827c478' } }

something else worth noting is i also regularly see a crash in openssl...im wondering if this is simply a different manifestation....here is the backtrace:

(gdb) bt full
#0  0x00007f30b2993b69 in ssl3_shutdown () from /lib64/libssl.so.10
No symbol table info available.
#1  0x00007f30b29ab3da in dtls1_shutdown () from /lib64/libssl.so.10
No symbol table info available.
#2  0x00000000004195a3 in janus_dtls_srtp_send_alert (dtls=0x7f301417be00) at dtls.c:781
No locals.
#3  0x000000000043498c in janus_ice_send_thread (data=0x7f2ffc036890) at ice.c:3307
        stream = 0x7f30911ab9e0
        now = 38868531429902
        handle = 0x7f2ffc036890
        __FUNCTION__ = "janus_ice_send_thread"
        pkt = 0x67fc40 <janus_ice_dtls_alert>
        before = 38868531169047
        audio_rtcp_last_rr = 38868530668993
        audio_rtcp_last_sr = 38867832845453
        video_rtcp_last_rr = 38868530668993
        video_rtcp_last_sr = 38867832845453
        last_nack_cleanup = 38868531429902
#4  0x00007f30b2e530f5 in g_thread_proxy () from /lib64/libglib-2.0.so.0
No symbol table info available.
#5  0x00007f30b19e7dc5 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#6  0x00007f30b171673d in clone () from /lib64/libc.so.6
No symbol table info available.

[lminiero]

Edited your comment to better frame the output. I see a couple websockets-related locks there, and the first in particular with 7 occurrences: I'll have a look to see if this leads us to the actual problem.

[lminiero]

The 2nd one is similar to the third, with many locks still held for the same mutex that had 7 occurrences in your attempt: old_wss_mutex. It's a mutex we have in place as with libwebsockets we don't have control on how the connection object is allocated/deallocated (it's all done automatically by the library), and so to avoid race conditions we take note of pointers that are supposedly not valid anymore in that table. When a pointer is reused for a new connection, we remove it from there. Notice that this pointer is NOT used in the reference counters branch: has anyone ever tried checking if the lock happens in there too?

The only relevant places where we access that mutex in master are janus_websockets_send_message, janus_websockets_destroy_client, and janus_websockets_session_over. We also access it when we get the LWS_CALLBACK_ESTABLISHED event in the libwebsockets loop, but I'd exclude this from the causes, as it only wraps a search on a table and releases the mutex right away. It might be more likely an occasional race condition/deadlock when one of the connections goes away, e.g., some circumstance where janus_websockets_destroy_client and janus_websockets_session_over are called by the same thread while the lock is still held. I'll try to investigate what may lead to such a case: of course, if others look at the same place and come up with such a possible scenario, please let me know!

[lminiero]

Update: the cause might indeed not be old_wss_mutex, but one of the clients' mutexes instead. If you check this snippet, where 0x7fe75c186890 is the affected mutex:

[..]
[transports/janus_websockets.c:janus_websockets_send_message:836:] LOCK 0x7fe770279620
[transports/janus_websockets.c:janus_websockets_send_message:849:] LOCK 0x7fe75c186890
[transports/janus_websockets.c:janus_websockets_send_message:858:] UNLOCK 0x7fe75c186890
[transports/janus_websockets.c:janus_websockets_send_message:859:] UNLOCK 0x7fe770279620
[..]
[transports/janus_websockets.c:janus_websockets_common_callback:1117:] LOCK 0x7fe75c186890
[..]
[transports/janus_websockets.c:janus_websockets_send_message:836:] LOCK 0x7fe770279620
[transports/janus_websockets.c:janus_websockets_send_message:849:] LOCK 0x7fe75c186890
[..]

since the mutex is apparently stuck in janus_websockets_common_callback (as evinced by the fact that it follows a successful unlock, while a subsequent attempt to lock again never goes on), then the whole libwebsockets event loop is stuck as well. There are no other locks in between the janus_mutex_lock(&ws_client->mutex) that locks and any subsequent janus_mutex_unlock(&ws_client->mutex) in that part of the code. I verified there are no scenarios where you could end up in an exit code that doesn't go through a janus_mutex_unlock for that mutex, so the best guess here is that something in between doesn't return, thus never allowing the mutex to be unlocked.

Not sure what it could be though:

• there's lws_write, where we pass the buffer the libwebsockets library should send; not sure if there's any case where this might hang (e.g., TCP related stuff);
• there's lws_callback_on_writable, but AFAIK that should never lock (it should only set a flag), unless it has some internal locking of its own for thread safeness;
• there's g_async_queue_try_pop, but this shouldn't block either (we use the try version exactly to avoid it waiting for anything), although some more locking may occur in the internals of the queue, being it the async version;
• nothing else pops to mind.

Any idea or feedback?

[lminiero]

It seems it might be the real cause of the issue in the third dump as well, even though it's old_wss_mutex that ends up physically deadlocking the libwebsockets event loop:

[transports/janus_websockets.c:janus_websockets_send_message:836:] LOCK 0x7f1f907ff620
[transports/janus_websockets.c:janus_websockets_send_message:849:] LOCK 0x7f1f7c100890
[..]
[transports/janus_websockets.c:janus_websockets_send_message:836:] LOCK 0x7f1f907ff620
[..]
[transports/janus_websockets.c:janus_websockets_common_callback:1032:] LOCK 0x7f1f907ff620

Here, the client's mutex never being unlocked, never unlocks old_wss_mutex either, and so when the common callback tries to access that for a new connection, it blocks indefinitely.

The stuff in janus_websockets_send_message that might cause it to hang is even less than the one from the previous post: either g_async_queue_push or lws_callback_on_writable. Again, not sure which could be the culprit, or even if I'm indeed on the right track (although I think so).

[sslivins]

i'd be happy to instrument things in that area more to help narrow things down

[lminiero]

The first thing that comes to mind are some pre- and post- log lines around those "candidates", and something that takes into account the mutex pointer, e.g.:

(in janus_websockets_send_message)

    janus_mutex_lock(&client->mutex);
    /* Convert to string and enqueue */
    char *payload = json_dumps(message, json_format);
    JANUS_LOG(LOG_INFO, "send_message:Pre-push (%p)\n", &client->mutex);
    g_async_queue_push(client->messages, payload);
    JANUS_LOG(LOG_INFO, "send_message:Post-push-Pre-writeable (%p)\n", &client->mutex);
#ifdef HAVE_LIBWEBSOCKETS_NEWAPI
    lws_callback_on_writable(client->wsi);
#else
    libwebsocket_callback_on_writable(client->context, client->wsi);
#endif
    JANUS_LOG(LOG_INFO, "send_message:Post-writeable (%p)\n", &client->mutex);
    janus_mutex_unlock(&client->mutex);
[..]

and same thing for the common callback, so around these key operations:

https://github.com/WatchBeam/janus-gateway/blob/impstar/transports/janus_websockets.c#L1123
https://github.com/WatchBeam/janus-gateway/blob/impstar/transports/janus_websockets.c#L1139
https://github.com/WatchBeam/janus-gateway/blob/impstar/transports/janus_websockets.c#L1148
https://github.com/WatchBeam/janus-gateway/blob/impstar/transports/janus_websockets.c#L1165
https://github.com/WatchBeam/janus-gateway/blob/impstar/transports/janus_websockets.c#L1181

It would make the logs much more verbose, but at least they should tell us once and for all if that's indeed one of those methods that's blocking everything, so that we can check why.

[sslivins]

also is there a risk that janus_websockets_destroy_client() would get called again with the same ws_client? ws_client->messages isnt set to null after g_async_queue_unref(ws_client->messages) so if this function was called again on an unref queue, im not entirely sure what might happen

[lminiero]

also is there a risk that janus_websockets_destroy_client() would get called again with the same ws_client? ws_client->messages isnt set to null after g_async_queue_unref(ws_client->messages) so if this function was called again on an unref queue, im not entirely sure what might happen

No, as it can only be called by the libwebsockets event loop, which is single threaded: the first time it's called, we set the destroy property to 1, and so a second time it would return right away.

[sslivins]

im currently having trouble with the existing verbosity of all the locks/unlocks, the logs get massive very quickly we dont have massive disks...if it enough to just instrument this area that would be ideal

[lminiero]

im currently having trouble with the existing verbosity of all the locks/unlocks, the logs get massive very quickly we dont have massive disks...if it enough to just instrument this area that would be ideal

You can try disabling the global locking debug, and only enable it in janus_websockets.c, or only for occurrences of client->mutex and old_wss_mutex: you can do that by turning the janus_mutex_lock and janus_mutex_unlock in janus_mutex_lock_debug and janus_mutex_unlock_debug only where you want to. This should limit the locking debug to what you're interested in, and greatly reduce the "spam".

[lminiero]

In the meanwhile, I'll also try to come up with a tiny random-times "stress" tool for WebSockets/Janus API, so that I can try and replicate the issue locally.

[sslivins]

perfect, will do...i should have results later today

[lminiero]

Ah, the irony! I had managed to quickly replicate this with the tiny stresser tool I implemented, but as soon as I added the same lines I suggested you, of course Janus is not deadlocking anymore... keeping it up to annoy Janus hoping it will happen soon :wink:

[lminiero]

Finally got it to happen, and from a first look in the log it seems the cause there was the lws_callback_on_writable in janus_websockets_send_message (after the last non-unlocked lock, I can see send_message:Post-push-Pre-writable but not send_message:Post-writable).

I'll do another round just to check if it happens in the same point, and then I'll evaluate.

[sslivins]

Btw,. I'm working out of the deadlock branch: https://github.com/WatchBeam/janus-gateway/tree/deadlock

https://www.dropbox.com/s/gy0ttpi4cn38hoz/janus-deadlock5.log.bz2?dl=0
https://www.dropbox.com/s/voug0o3t1dxd463/janus-deadlock6.log.bz2?dl=0
https://www.dropbox.com/s/rjl74k3va6h5qn7/janus-deadlock7.log.bz2?dl=0
https://www.dropbox.com/s/hdzxhlv8swu4q0k/janus-deadlock8.log.bz2?dl=0

[lminiero]

Sorry for the delay, but it will take some time before I can look into this. Today is Labor Day (National holiday in Italy) and tomorrow I'll fly abroad for an event for a few days. Anyway, I did some more dumps of my own too, so I have material to investigate when I can.

[lminiero]

Just came back to the office after attending two different events, so sorry for the lack of feedback. I'll give a look at the logs between today and tomorrow in order to check if I can get to the real source of the issue.

[lminiero]

Contacted the lws developers for info on what might cause lws_callback_on_writable never to return, and they said locking is only used if the library is compiled with a LWS_MAX_SMP value different than 1, the default.

I'm now trying to attach via gdb to Janus as soon as it deadlocks, but obviously I've been stressing it for more than an hour and nothing happened yet... not sure if I'm using a different library than when I could replicate the issue at the time: now I'm using the version my Fedora 25 ships in the repos, which apparently has LWS_MAX_SMP=1. One thing you guys might want to check is what LWS_MAX_SMP is set to in cmake in your building environment.

I'll keep you posted in case I manage to deadlock it again and get some gdb info.

[connectarena]

If we use libwebsockets with single thread, won't it attract extra delay? Any ways we started to use libwebsockets with single thread and it is running with out deadlock since 36 hours.

[lminiero]

libwebsockets is conceived to be single thread, so there shouldn't be any issue. If you think about that, node.js is single threaded as well, and there's usually no problem in basing HTTP/WS services on top of that. Considering the WS support in the Janus API is only needed for signalling purposes (no really intensive traffic), I don't expect that to be an issue.

Thanks for the feedback on the lack of deadlocks in that case!

[lminiero]

@vecio @shrhoads @zombiecong @sslivins @atyenoria just pinging you guys as you contributed to the issue with feedback on this happening to you. As explained in a previous note, which addressed a comment from the lws developers, just building your library with LWS_MAX_SMP=1 in cmake should fix this, so please let me know if that's not the case.

[sslivins]

i will try this today @lminiero and let you know the results over the next 24h...thanks again for tracking this down

[sslivins]

btw the default value of LWS_MAX_SMP is 32 in libwebsockets 2.2

[lminiero]

Weird, the lws developer told me the default was 1. My Fedora ships a 2.1 rpm in the repos, and I couldn't replicate the issue with that, which makes me think that one is using 1 (seems to be confirmed by looking at the cmake file).

[sslivins]

again, this is i build from source and dont put anything explicit for the cmake...also corresponds with their docs: https://libwebsockets.org/lws-api-doc-master/html/md_README_8coding.html

[sslivins]

so just to update things...,i am still experiencing some deadlocks but it's many many orders of magnitude fewer...i still need to evaluate if these are the same root cause or something else, i'll get you more info on monday

[atyenoria]

For me, it won't happen. It seems to be solved.
[spec]
Video room with ref-count latest commit(4daf434e201). Cmake libwebsocket with LWS_MAX_SMP=1(Default is 32)
All 20 Chrome tab(3pc) publishing their own video and audio, I tried to disconnect and connect at the same time for about ten times. no crash and no websocket deadlock.

In the past, I can confirm that this happens frequently.

[lminiero]

Something weird I just noticed... I wanted to add a check for LWS_MAX_SMP in the plugin code, so that if it's different than 1 we can print a warning, but when I print it out it's 32 for me! Which means that my Fedora shipped version, which is 2.1.0, is still using the default value of 32, and yet I couldn't replicate the issue anymore? Maybe only an issue with 2.2 and LWS_MAX_SMP > 1 then?

[idubinets]

I faced the same issue. LWS_MAX_SMP is set to 32 by default. I rebuilt the library with LWS_MAX_SMP = 1.
let's see how it will work. I will let you know

[IvRRimum]

Adding to this discussion:

I am using websockets, i recompiled libwebsockets with LWS_MAX_SMP=1 and i still managed to get the deadlock.

But here's the weird behaviour of the deadlock: I am using 2 plugins in my janus installation:
1) audiobridge
2) videoroom.
When a deadlock happens on audioroom, i can still access and use videoroom. I don't know if this is related tho.
Also i wanted to add that i am using janus-gateway version from Dec 20, 2016.

I ran the LOCK/DEADLOCK script and i got these: https://pastebin.com/zAa4iNLC

How to reproduce: Create 6 chrome tabs and join a single room. Do the same on pc 2. and connect from 3rd device(in my case its mobile app). Run automation script that refresh -> join room -> unmute for 2 seconds -> refresh -> join....

After a while the audiobridge will deadlock.

EDIT: After further crashin, the first lines of the LOCK/UNLOCK script change, depending on the situation where it deadlocked(next time its not in my room_helper:radio_thread, but in list_rooms, etc). So that probably means it deadlocks before and then tries to lock again on already locked mutex.

[lminiero]

If other plugins work, then it's not websockets related (unless the plugin
still works when accessed via another transport like HTTP, for instance,
which I find unlikely), so please let's not confuse issues. It would be
better to open another issue on the audiobridge deadlocking with the info
you found.

Il 04 giu 2017 5:13 PM, "Ivrrimum" [e-mail] ha scritto:

Adding to this discussion:

I am using websockets, i recompiled libwebsockets with LWS_MAX_SMP=1 and i
still managed to get the deadlock.

But here's the weird behaviour of the deadlock: I am using 2 plugins in my
janus installation:

1. audiobridge
2. videoroom.
   When a deadlock happens on audioroom, i can still access and use
   videoroom. I don't know if this is related tho.
   Also i wanted to add that i am using janus-gateway version from Dec
   20, 2016.

I ran the LOCK/DEADLOCK script and i got these:
https://pastebin.com/zAa4iNLC

How to reproduce: Create 6 chrome tabs and join a single room. Do the same
on pc 2. and connect from 3rd device(in my case its mobile app). Run
automation script that refresh -> join room -> unmute for 2 seconds ->
refresh -> join....

After a while the audiobridge will deadlock.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/meetecho/janus-gateway/issues/732#issuecomment-306046210,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADg5vFCJYQShKCiYGNjgEeZv9gz-vc9cks5sAsmrgaJpZM4LbiaO
.

[IvRRimum]

Hey @lminiero!

Yeah, makes sense. created issue here.

[shrhoads]

Just reporting in on this, LWS_MAX_SMP=1 seems to have solved the issue for me.

[lminiero]

Closing then, thank you all for the feedback!