streaming plugin: mountpoint resources are not released on destroy

[kazzmir]

I'm using janus to relay an RTP stream. It seems that if I dynamically create/destroy the mountpoint then in some cases the resources for the mountpoint are not free'd. In particular, the UDP ports bound by janus for the audio/video source are not deallocated when the "destroy" request is sent to the streaming plugin. This is because the refcount of the mountpoint reaches 1 (I verified this by adding JANUS_LOG statements), but does not reach 0 and thus the refcount cleanup functions do not run. The cleanup function that would close the UDP ports is janus_streaming_rtp_source_free.

In my situation I do this:

janus management process:
  send "create" request to the streaming plugin

client 1:
  send "watch" request to the streaming plugin

janus management process:
  send "destroy" request to the streaming plugin

In this case the refcount does not reach zero. If client 1 does not send "watch" then the refcount does reach zero, that is a "create" followed by "destroy" works correctly. Also this sequence works if client 1 disconnects or otherwise destroys its janus handle.

When looking at the code for "destroy" it seems like janus cleans up correctly so I'm not sure what the issue is.

janus-gateway/plugins/janus_streaming.c

Line 3328 in c3c347e

/* FIXME Should we kick the current viewers as well? */

This line says /* FIXME Should we kick the current viewers as well? */ but just a few lines later it looks like the viewers list is iterated over and closed, so is that FIXME out of date?

GList *viewer = g_list_first(mp->viewers);
while(viewer) {
   ...
   mp->viewers = g_list_remove_all(mp->viewers, s);
  viewer = g_list_first(mp->viewers);
}

I can provide a test case if this description is not reproducible on its own.

[lminiero]

The proper way of debugging reference counter leaks is uncommenting the REFCOUNT_DEBUG in refcount.h and recomment, as that will track the lifecycle of all references, including code lines, on the log: it will also print the references still alive when you cleanly close Janus, meaning that you can then crawl the log for those references and see where they were initialized, who increased them, who decreased them and where, and where there may be the missing unrefs (e.g., X took a reference, but then didn't release it). My guess is that in your case the mountpoint is still referenced by users, and you still have users related to the mountpoint for some reason.

[kazzmir]

My guess is that in your case the mountpoint is still referenced by users, and you still have users related to the mountpoint for some reason.

I agree this is what it looks like, but why isn't it the case that destroying a mountpoint kicks off the users? Otherwise the users can hold the server hostage by preventing the server from releasing resources as long as the users stay connected.

Is there any other way of forcing users off of the server (without completely stopping the janus process)?

[lminiero]

why isn't it the case that destroying a mountpoint kicks off the users?

It should, the code is there (see close_pc call in the loop on all viewers). Again, you can check what I mentioned in the previous message to see which reference is held and why.

[kazzmir]

I tracked down the issue: the root cause was the the same session was being added to the mountpoint->viewers list multiple times, and the places in the code where the viewers is iterated over removes all instances of the viewer rather than just the current viewer being iterated over.

For example in janus_streaming_process_synchronous_request is a loop that iterates over all viewers attached to the mountpoint in the "destroy" request:

janus-gateway/plugins/janus_streaming.c

Line 3369 in c3c347e

mp->viewers = g_list_remove_all(mp->viewers, s);

If the same session object appears in the mp->viewers list more than once then this loop will call gateway->close_pc() once on that session. That will lead to a call to janus_streaming_hangup_media_internal, which does

janus-gateway/plugins/janus_streaming.c

Line 3997 in c3c347e

if(g_list_find(mp->viewers, session) != NULL) {

mp->viewers = g_list_remove_all(mp->viewers, session);

So the mountpoint will be dereffed once, and all session objects are then removed from the mp->viewers. The "destroy" handler will also remove all instances of the session from the mp->viewers list, so thats a bit overkill probably.

My first attempt at fixing this was to only call g_list_remove(mp->viewers, session) rather than remove_all and iterate over the mp->viewers such that the mountpoint ref is decremented once for each session found. This ended up not quite working out, and I think its the wrong approach anyway.

A better question is why is the same session in the mp->viewers list to begin with. A few places in the code seem to try to maintain the invariant that a session only appears once in a viewers list. First of all, I verified that a session is added multiple times to the viewers list by adding a few more JANUS_LOG statements that resulted in the following:

[Thu Dec 19 22:34:46 2019] [4239] Adding viewer 0x7f9374f04bb0 to mountpoint 0x7f9374f05420 id 4681534374840623
[Thu Dec 19 22:34:46 2019] [4245] Viewers for 0x7f9374f05420 4681534374840623 is now 2
[Thu Dec 19 22:34:46 2019] [4239] Adding viewer 0x7f9374f04bb0 to mountpoint 0x7f9374f05420 id 4681534374840623
[Thu Dec 19 22:34:46 2019] [4245] Viewers for 0x7f9374f05420 4681534374840623 is now 3

The reason this occurs is that the client repeatedly sends watch requests. I made two changes to the code to prevent the same session from being added to a mountpoint.

1. Decrement the mp->ref if the session->mountpoint == mp in janus_streaming_handler:

if(session->mountpoint != NULL) {
     if(session->mountpoint != mp) {
         ....
      } else {
        janus_refcount_decrease(&mp->ref); // added this line
         /* Simple renegotiation */
        JANUS_LOG(LOG_VERB, "Request to update mountpoint/stream %"SCNu64" subscription (no restart)\n", id_value);
         session->sdp_version++; /* This needs to be increased when it changes */
         goto done;
       }
}

This works because a few lines up just before the check for a pin the mp->ref is increased.

janus-gateway/plugins/janus_streaming.c

Line 4102 in c3c347e

janus_refcount_increase(&mp->ref);

2. Don't add the session to the viewers list if the session is already part of the list
   

   janus-gateway/plugins/janus_streaming.c

   Line 4334 in c3c347e

   mp->viewers = g_list_append(mp->viewers, session);

if (!g_list_find(mp->viewers, session)){
  mp->viewers = g_list_append(mp->viewers, session);
}

With these two changes the mountpoint has its refcount release function called when the "destroy" request is sent for the mountpoint.

[kazzmir]

Actually #2 can be ignored, adding the same session to the viewers list multiple times seems to be fairly harmless. The only thing that actually matters is decrementing the refcount for the mountpoint in case the session->mountpoint == mp.

[lminiero]

The reason this occurs is that the client repeatedly sends watch requests

But that shouldn't lead to this issue. We have a fence in place, protected by a mutex, to make sure the same session can't issue multiple watch requests: if they try to ask for a different mountpoint, the request is rejected, while if it's the same mountpoint, it's handled as a renegotiation attempt.

I guess the latter is probably what's broken. I'm not sure simply decrementing the refcount is enough, because it may fix the leak, but it's not fixing the API inconsistency. If this is not a renegotiation, but simply a bad use of the API by clients, we should reject those additional watch requests too.

[lminiero]

The commit above should fix both issues. Please let me know if that's not the case.

[kazzmir]

This seems to work, the mountpoint resources are free'd on destroy, and I see messages in the log about already watching the mountpoint.

[Fri Dec 20 12:05:50 2019] [ERR] [plugins/janus_streaming.c:janus_streaming_handler:4146] Already watching mountpoint 1073089490240053
[Fri Dec 20 12:05:50 2019] [8886006316798035] Sending event to transport...
[Fri Dec 20 12:05:50 2019] Sending event to janus.transport.http (0x7f96e4711160)
[Fri Dec 20 12:05:50 2019] Got a Janus API event to send (0x7f96e4711160)
[Fri Dec 20 12:05:50 2019]   >> Pushing event: 0 (Success)
[Fri Dec 20 12:05:50 2019] [ERR] [plugins/janus_streaming.c:janus_streaming_handler:4146] Already watching mountpoint 1073089490240053
[Fri Dec 20 12:05:50 2019] [8886006316798035] Sending event to transport...
[Fri Dec 20 12:05:50 2019] Sending event to janus.transport.http (0x7f96e4711160)
[Fri Dec 20 12:05:50 2019] Got a Janus API event to send (0x7f96e4711160)
[Fri Dec 20 12:05:50 2019]   >> Pushing event: 0 (Success)
[Fri Dec 20 12:05:50 2019] [ERR] [plugins/janus_streaming.c:janus_streaming_handler:4146] Already watching mountpoint 1073089490240053