Janus-gateway: Open file descriptor leak

[tgabi333]

janus (master and 0.2.4 and even 0.2.3) has an increasing open file descriptor count as time passes.

On our test system within only one week and with 10 videoroom calls we got 922 files open (compared to ~700 when janus starts)

As i see the problem is around RTCP BYE handling.

I found a way how to reproduce it with echotest plugin:

1. run this thing in the background: watch "lsof | grep janus | wc -l"
2. use websocket to connect to janus (don't know if it is relevant)
3. change janus.js to not send the {"janus": "destroy" } event (comment out this line)
4. start echotest in the browser
5. reload your browser tab

After the cleanup processes you got nine more file handlers than before.

Session end log for normal exit (with destroy message): https://pastebin.com/EtuqFK68
Session end log for leftover file handles (without or a late destroy message): https://pastebin.com/yr0zXrp7
A diff of new file descriptors list: https://pastebin.com/QCszXtEj

Maybe videoroom plugin is affected too.

[lminiero]

If you're not sending destroy, then the session and handle may still be there, meaning you have to wait for the timeout to kick in (by default 60 seconds). If you disabled the timeout value in janus.cfg (session_timeout = 0) then the session timeout cleanup will never take place, and things will indeed leak, but we already discourage this policy in the configuration file.

Have you tried checking with the Admin API if those sessions/handles are still there before you shut down? (and again, after you've waited for the session timeout cleanup to take place?)

[tgabi333]

session_timeout is on default 60s. After several minutes the file handlers still there.
Yep, there is no active sessions in Admin API.

What i found now is this: no matter if we send janus:destroy or not on websocket, if janus got an RTCP BYE while an websocket connection is open, there will be a leakage.

Open file descriptors with destroy
922 - no connection
988 - running one echotest
946 - pc.close() (changed the code to be able to close the PeerConnection manually from console)
931 - echotest page refresh (sends destroy and closes websocket)
925 - after a minute

Open file descriptors without destroy
934 - no connection
1006 - running one echotest
964 - pc.close()
949 - echotest page refresh (closes websocket)
949 - after a minute

Its not constant how many open descriptors left. Usually nine.

We use janus as we connect to it from nodejs and not directly from browsers, that's why we have this problem i think.

[MvEerd]

I notice a similar issue using the videoroom plugin without any remaining sessions;

(the drop in the graph is Janus restarting, this is on a fresh install of Ubuntu 16.04)

I'll keep an eye on this in case I notice something or can be of any help debugging

[lminiero]

Can you guys check the latest master? As part of another issue I was made aware of, I improved the way the session cleanup works: https://github.com/meetecho/janus-gateway/commit/5ffcf9a8e999f26555e823d81ab8f20cd1c427d2

[MvEerd]

Thanks Lorenzo 👍 , I've deployed it right away and will keep an eye on the number of open file descriptors

[tgabi333]

Sorry, its not helped. I've created a video: https://www.youtube.com/watch?v=q2pgjYdPKLM

[MvEerd]

I also continue to have [eventfd] file descriptors left open with 5ffcf9a
after 2 days of using the Videoroom plugin with HTTP transports it's gone up from 200 to 8000 despite having the same number of sessions

[lminiero]

Ack, thanks for the feedback :+1:

[lminiero]

We don't use eventfd, though: maybe one of the dependencies?

[tgabi333]

played with current libnice master, the result is the same :(

[tgabi333]

I'm not sure its helps or not, but as i see, the iceloop thread opens a file descriptor (eventfd - and polling it) and that file handler won't be terminated later.

https://pastebin.com/vMHgJ4YF

Further investigations:
Here is the leaked info: https://pastebin.com/aaTdG9U8
What i see is:

• eventfd2 calls creates file handler 17 and 18 from thread called pool
• file handler 17 and 18 got a write calls
• file handler 18 is closed by thread called iceloop
• file handler 17 remains open

and here is a good one: https://pastebin.com/TSZQhyHc

• eventfd2 calls creates file handler 18 and 19 from thread called pool
• file handler 18 and 19 got a write calls
• file handler 19 is closed by thread called by a thread called janus
• file handler 18 is closed by thread called by a thread called janus
• no remaining file handler

[lminiero]

pool may be the name Glib gives to the GThreadPool we create to handle requests. Each request is served by a thread in that pool, including those that involve a negotiation and so create the ICE stack, which might explain why that's the thread that creates those file descriptors.

The thread called janus might be everything, instead, so that doesn't help much. If my assumption on the pool being one of the tasks is correct, though, this means that those descriptors are not freed after a request (e.g., "destroy") but by one of the generic threads/workers in the Janus core itself (otherwise they'd have pool too).

That said, have you tried launching Janus with the -U -u flags? This will force libnice to always gather a single port per call, instead of many that eventually get down to one after the negotiation. If the issue doesn't happen there, it might mean we're still fighting the issue we solved in #154 for some reason.

[MvEerd]

Thanks for the extra information to you both! 👍
I tried launching janus with the -u -U flags but it looks like it still leaves some file descriptors open
The number of file descriptors that are left open seems to match with the number of publishers I subscribed to before closing the tab

I'll try setting a breakpoint in gbd and testing this manually later to see if that shows anything useful

[lminiero]

Not sure if I mentioned this already, but make also sure you're not using ice_tcp=true in janus.cfg, as IIRC there were known leaks in libnice with respect to TCP candidates.

[lminiero]

Reffing issue #587 where I remember seeing this discussed, not sure if it's still relevant.
Edit: adding the post on the libnice ML as well, https://lists.freedesktop.org/archives/nice/2015-November/001268.html

[MvEerd]

Thanks for the heads up!
Just to confirm, I have ice_lite and ice_tcp commented out so they should not be used

[lminiero]

Just to confirm, I have ice_lite and ice_tcp commented out so they should not be used

It was worth a try! :slightly_smiling_face:
I tried playing a bit with EchoTest and VideoRoom, and using the following command to track the number of port bindings for UDP before, during and after the sessions end:

sudo netstat -tulpn | grep janus | grep udp | wc -l

but they always get back to the initial value after the handle is cleaned up (which was 14 in my case), so it doesn't look like I'm getting leaks caused by libnice (but this command may not be the best way to check that). Not sure how we can check other info about the leaks you're getting instead.

Have you tried matching those file descriptors to specific ports, to check if we can see what they were related to?

[MvEerd]

It was thanks 👍

All the file descriptors that are left open look like this, I don't think they're keeping any ports open

janus   13624 user 5767u  a_inode               0,11        0     8598 [eventfd]

I get a list of these by running lsof -p $JANUS_PID
lsof -p $JANUS_PID | grep eventfd | wc -l returns 5692 while lsof -p $JANUS_PID | grep UDP | wc -l returns 71 (which is the same number as your netstat command returns)
I also don't see these in netstat when I leave outgrep udp

[MichaelB76]

Using our modified plugin (based on the the SIP plugin) we're also getting the following leak on a rapid session disconnection and reconnection:

janus 35922 root 54u a_inode 0,9 0 5342 [eventfd]

But if I end the session and reconnect a few seconds later I don't get this, so it may be timing dependant. I can reproduce this consistently.

I'm using lsof -a -p, piping the output to a file before and after the reconnection for easy comparison.

Running Janus overnight with three sessions connected and lots of activity I saw the FD count increase by one. I also see a very small fluctuation in the FD count occasionally (1 or 2). We updated our code to Master on Monday, commit 6b634c29fdb302b14e68fa5defaa33cb61247248 I beleive.

I don't know if something is using a thread pool? libmicrohttpd?

[lminiero]

libmicrohttpd uses a thread pool if you configure it like that, I think. The default configuration is one thread per request (something I'd like to change soon, that's probably overkill). In the Janus core, we use a thread pool for the management of requests coming from transports.

That said, while a colleague of mine managed to replicate the issue per the previous instructions, I can't seem to be able to replicate it in my setup instead. The only difference seems to be the OS, as my laptop uses Fedora 25: libnice may be slightly different, but the one I got from the repos is still a 0.1.13 (possibly with some patches added by the Fedora maintainers). Still looking into the possible cause.

[MichaelB76]

OK thanks, I'll check what versions of libnice and libmircohttpd we are using.

[tgabi333]

We are not using libmicrohttp (checked with ldd janus). I've tried libnice 0.1.13 and master, both the same result.

[MvEerd]

Libnice 0.1.13-0ubuntu2 here,
after using the videoom plugin with 1 room for 3 days there are 14661 eventfd file descriptors open
(there are 2 UDP file descriptors and 86 others, the room is nearly empty now)

I'll try libnice master to see if that makes a difference

[tgabi333]

Here are more details i've found:
with sudo strace -f -k -p 19741 -e trace=close,eventfd2

Here is a good version: https://pastebin.com/a7W1XvHq
Here is a wrong version: https://pastebin.com/LhGfJ3aK

The difference is that the wrong version didn't call close(14)

You can see in the good version that close(15) and close(14) comes from the same stack trace:

janus_ice_webrtc_free -> g_main_context_unref (handle->icectx) -> nice_agent_dispose

And in nice_agent_dispose call:
nice_agent_dispose+0x133 is closed fd15
and
nice_agent_dispose+0x205 should have closed fd14

So the problem is around handle->icectx

is this code correct? https://github.com/meetecho/janus-gateway/blob/master/ice.c#L3409

[lminiero]

@atoppi had just reached pretty much the same conclusion, and was telling me about the very same thing just a few minutes ago! :smile: He was just in the process of recompiling Janus to make a test, by commenting out that handle->icectx = NULL.

The only other place where we set that value to NULL, in fact, is indeed in janus_ice_webrtc_free:

        g_main_context_unref (handle->icectx);
        handle->icectx = NULL;

but there may be a race condition where, if we set the context to NULL, the unref is never done for the context itself.

[lminiero]

Live update: according to him, even commenting the handle->icectx = NULL; at line 3409, the leak still occurs. Waiting for some more feedback from him before I can add more.

[lminiero]

As a side note (something I've just discussed with @atoppi, who is the team member here who's physically digging into this), I'm seeing that we also set handle->iceloop to NULL in the same branch, something we don't do anywhere else (where we also do a g_main_loop_quit followed by a g_main_context_wakeup). Considering there are branches in the code that only do something if handle->iceloop has a value, it might be worth to try commenting that one out as well.

[tgabi333]

I've just commented out that whole if (https://github.com/meetecho/janus-gateway/blob/master/ice.c#L3405) and it looks like working.

[lminiero]

Mh, I think the g_main_loop_quit (and the wake up call) is still needed, though, otherwise the libnice loop might not exit under certain conditions. Have you tried just commenting out the two NULL assignments?

[lminiero]

@atoppi confirms that just commenting out the NULL stuff works for him.

[tgabi333]

only commenting handle->icectx = NULL; is still leaves a file handler for me

[lminiero]

I meant both: icectx and iceloop.

[tgabi333]

yes, it works :)

[lminiero]

@MvEerd can you check if this fixes it for you too? Before applying the fix in master, I'd like to double check that this doesn't introduce any regression, but knowing that it fixes the issue for all the people who could replicate it (I feel excluded now :smile: ) definitely helps getting us closer to close this.

[MvEerd]

Deploying this right away myself as well (commenting out https://github.com/meetecho/janus-gateway/blob/master/ice.c#L3407 and https://github.com/meetecho/janus-gateway/blob/master/ice.c#L3409 right?) Will keep you posted when I get back!

[lminiero]

Mh, looks like this is not the fix we're looking for, or at least only part of it, as this crashes Janus in @atoppi's tests. Specifically, if you wait for the cleanup (probably when getting rid of the handle), then an assertion somewhere fails and Janus crashes. We'll look into this next.

[lminiero]

PS: obviously (unsurprisingly?) I can't replicate it myself, in my setup... please let me know if you're getting the crash too. It should be enough to detach the handle, or let the session time out so that the handle is detached automatically, after the missing destroy you were already doing.

[lminiero]

Apologies, I wrote too soon... the tests that made Janus crash were on different changes @atoppi was playing with. Just removing the two lines we mentioned should be safe, and works for him too. Waiting for feedback from you guys now to confirm we can add to master, thanks!

[cacheworks]

I did get crashes commenting out those two lines myself so I reverted for now
Do you want me to get some AddressSanitizer or GDB output for that?

[lminiero]

If you could do that it would help, thanks!

Il 08 set 2017 7:12 PM, "cacheworks" [e-mail] ha scritto:

I did get crashes commenting out those two lines myself so I reverted for
now
Do you want me to get some AddressSanitizer or GDB output for that?

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/meetecho/janus-gateway/issues/983#issuecomment-328161954,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADg5vEEpWS14d8UDVwUOMF-RGqiFHYzEks5sgXVqgaJpZM4PH6lo
.

[MvEerd]

With those lines commented out I got the following crash after two hours of use which might be related to what you referred to in https://github.com/meetecho/janus-gateway/issues/983#issuecomment-328139675
(But I don't think file descriptors stayed open during that time)

libnice:ERROR:agent.c:2342:agent_signal_component_state_change: assertion failed: (TRANSITION (DISCONNECTED, FAILED) || TRANSITION (GATHERING, FAILED) || TRANSITION (CONNECTING, FAILED) || TRANSITION (CONNECTED, FAILED) || TRANSITION (READY, FAILED) || TRANSITION (DISCONNECTED, GATHERING) || TRANSITION (GATHERING, CONNECTING) || TRANSITION (CONNECTING, CONNECTED) || TRANSITION (CONNECTED, READY) || TRANSITION (READY, CONNECTED) || TRANSITION (FAILED, CONNECTING) || TRANSITION (FAILED, GATHERING) || TRANSITION (DISCONNECTED, CONNECTING))

[lminiero]

Thanks for the feedback, we're playing with some tentative changes to see if we can fix that. If you want to see for yourself what we're playing with now, you can try applying this patch manually. @atoppi hasn't published it as a PR yet as we're still in the exploring phase, and so tons of commits until we converge would only mess the log.

[lminiero]

@tgabi333 @MvEerd have you tried the patch by any chance? It seems to be working fine in our tests, although we're still doing some hammering to see if it is indeed working as expected.

[tgabi333]

@lminiero @atoppi give me one or two days please :)

[cacheworks]

Sorry for the confusion and delay in getting back here, it seems that my issues were caused by me trying libnice master earlier (despite pkg-config --cflags --libs nice returning libnice 0.13 it was still being built against the wrong symlink)
I've now got things stable again and will test the patch overnight 👍
Thanks for your efforts @atoppi and @lminiero !

[tunderdomb]

@lminiero: @tgabi333 Asked me to try the patch on our project. I applied it against the current master, and at first glance it looks like has solved the problem!

I used watch "lsof | grep janus | wc -l" to monitor the count, and saw it increase by 20 on each page reload. After I applied the changes the leak has seemingly disappeared. Did multiple test session to confirm.

[lminiero]

@tunderdomb good to know, thanks! Please test on longer runs and with multiple users too, if possible, in a way that is as close as possible as your usual scenarios. I want to be 100% sure we're not introducing anything that may suddendly die after 2-3 hours for no reason, basically. The tests we're carrying on are aimed at that, mostly, so confirmation that others are not getting issues will help.

[lminiero]

Now that @atoppi prepared a PR, I have something to merge: as soon as I have a greenlight from you guys, I'll go on with that.

[tgabi333]

we just tested in house the PR, it has a much better results. When we waited for connections to build up properly janus cleaned up everything. But if we reload browsers without waiting for the connection to build up we still got a leaking eventfd descriptors.

So i think this pr is solving majority of the leaks.

We have to found a use case for reproducing this minor leak.

[atoppi]

@tgabi333 regarding this latest scenario you described, are you still skipping the destroy request on the page refresh? I mean the lines you suggested to comment out, are still commented or not?

[lminiero]

@tgabi333 do you mean as in users trying to create a PC on a valid handle, which either takes a while or isn't completed yet, and then closing/refreshing the page? Have you checked if sending a "destroy" results in the same problem? (my guess is yes).

[tgabi333]

@lminiero @atoppi give me one or two days to figure out what scenario leaks, the PR imo is good, it works with our use cases, but not covers everything. let's say its 95%.

ps: we always send destroy since weeks.

[lminiero]

Ok, waiting for the final ack from @MvEerd too and then I'll merge the existing PR. We can work on the other problem with another patch.

[MvEerd]

Ack!
I've let this run during peak hours with all kinds of users connecting and disconnecting.
That previously caused the eventfd file descriptors to increase to 3000+ overnight but this afternoon I only see 13 eventfd fds which is normal for the 10 UDP file descriptors that are open so this looks fully resolved here (this is all without -u -U as well)
Thank you @atoppi @lminiero 🎉 !

[lminiero]

Thanks! Merging then :+1:

[lminiero]

Closing as we merged @atoppi's fix.