Memory loss

[mirkobrankovic]

We have been running 0.10.10 version lately and noticed quite some mem loss over time:



Running master in Valgrind showed me two places of loss, one initiating videoroom from file which was there before if i remember correctly:

==622494== 48 (24 direct, 24 indirect) bytes in 1 blocks are definitely lost in loss record 441 of 797
==622494==    at 0x4839809: malloc (vg_replace_malloc.c:307)
==622494==    by 0x4B4BBB8: g_malloc (in /usr/lib64/libglib-2.0.so.0.6600.8)
==622494==    by 0x4B63481: g_slice_alloc (in /usr/lib64/libglib-2.0.so.0.6600.8)
==622494==    by 0x4B38F37: g_list_append (in /usr/lib64/libglib-2.0.so.0.6600.8)
==622494==    by 0x4210FD: janus_config_get_categories (config.c:507)
==622494==    by 0x718EE51: janus_videoroom_init (janus_videoroom.c:2217)
==622494==    by 0x415077: main (janus.c:5307)

but this one is new on incoming requests:

==622494== 192 (80 direct, 112 indirect) bytes in 1 blocks are definitely lost in loss record 766 of 797
==622494==    at 0x4839809: malloc (vg_replace_malloc.c:307)
==622494==    by 0x4B4BBB8: g_malloc (in /usr/lib64/libglib-2.0.so.0.6600.8)
==622494==    by 0x451430: janus_session_create (janus.c:743)
==622494==    by 0x454E97: janus_process_incoming_request (janus.c:1075)
==622494==    by 0x45EADD: janus_transport_requests (janus.c:3377)
==622494==    by 0x4B71401: ??? (in /usr/lib64/libglib-2.0.so.0.6600.8)
==622494==    by 0x53923F8: start_thread (in /usr/lib64/libpthread-2.32.so)
==622494==    by 0x5549B52: clone (in /usr/lib64/libc-2.32.so)

Let me know if I need to provide more details.
Thanks up front

[lminiero]

Better to use libasan to track leaks, valgrind makes everything too slow to be meaningful.

[mirkobrankovic]

Asan is reporting the same:
https://pastebin.com/xmPR2NSa

[atoppi]

@mirkobrankovic can you list the steps to reproduce the leak ?

[mirkobrankovic]

@atoppi using Audiobridge and Videoroom plugins, 3 members in each, all 3 members subscribe to other 2 in Videoroom.
After that I'm closing the client browser tabs, but signaling wise, backend is sending leave requests for each member:
{"body":{"request":"leave","room":1000042710}}
Followed by detach for each member:
{"handle_id":4533215128961913,"janus":"detach","session_id":5681561440596542}
and finally room destroy:
{"request":"destroy","room":1000042710},"handle_id":8788924592374833,"janus":"message","session_id":5681561440596542,"transaction":"#Reference<0.314938189.3790864391.37004>"}

[atoppi]

Why are you not destroying sessions too ?

[mirkobrankovic]

Unfortunate/Accidental design flow I guess :D
Since it is a WS connection between Signaling backend and Janus media backend it can all be done over one/or few WS connection/s.
We keep one WS conn always active as a keepalive and both Audiobridge and Videoroom creation destruction, user requests all is done over second WS connection that is destroyed later (when Elixir process dies)

[mirkobrankovic]

for example:
https://pastebin.com/bMBXd977

but I do have a reclaim_session option:
reclaim_session_timeout = 120
But in our use case it will never be reclaimed, always new one created

[atoppi]

It is not clear how many sessions are you using though (connections != sessions).
Having a pool of connections is okay, but if you are creating a janus session per user, you should also destroy it when the user leaves (or closes the tab).

[mirkobrankovic]

This use case creates 4 janus sessions over one ws connection (each janus session is responsible for one plugin, for all users) and it is destroyed in the end.
Sorry for not being clear enough

[atoppi]

Another test I did:

• enable session reclaim (30 seconds)
• enter videoroom demo with 3 participants
• refresh all tabs
• close janus

Some leaks are reported, but I think they are the data being hold by janus due to session reclaiming.
If I wait the session reclaim timeout and then close the server, no leaks are reported.

Anyway this is not exactly the same signalling as yours, because the connection here is being torn down when the tab refreshes.

[mirkobrankovic]

@atoppi thanks, I will do some more tests and come back if I find new info

[atoppi]

Managed to reproduce exactly your same trace

==38907==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 80 byte(s) in 1 object(s) allocated from:
    #0 0x4a1eed in malloc (/usr/local/janus/bin/janus+0x4a1eed)
    #1 0x7f577c661e98 in g_malloc ../../../glib/gmem.c:102:13
    #2 0x5676fb in janus_session_create /home/atoppi/src/janus-gateway/janus.c:743:29
    #3 0x56d452 in janus_process_incoming_request /home/atoppi/src/janus-gateway/janus.c:1075:13
    #4 0x5aeac7 in janus_transport_requests /home/atoppi/src/janus-gateway/janus.c:3377:5
    #5 0x7f577c685ad0 in g_thread_proxy ../../../glib/gthread.c:807:20
    #6 0x7f577bf9e608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477:8
    #7 0x7f577be9f292 in clone /build/glibc-eX1tMB/glibc-2.31/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Indirect leak of 64 byte(s) in 1 object(s) allocated from:
    #0 0x4a1eed in malloc (/usr/local/janus/bin/janus+0x4a1eed)
    #1 0x7f577c661e98 in g_malloc ../../../glib/gmem.c:102:13
    #2 0x56a407 in janus_request_new /home/atoppi/src/janus-gateway/janus.c:888:27
    #3 0x56d672 in janus_process_incoming_request /home/atoppi/src/janus-gateway/janus.c:1084:21
    #4 0x5aeac7 in janus_transport_requests /home/atoppi/src/janus-gateway/janus.c:3377:5
    #5 0x7f577c685ad0 in g_thread_proxy ../../../glib/gthread.c:807:20
    #6 0x7f577bf9e608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477:8
    #7 0x7f577be9f292 in clone /build/glibc-eX1tMB/glibc-2.31/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Indirect leak of 48 byte(s) in 1 object(s) allocated from:
    #0 0x4a2062 in calloc (/usr/local/janus/bin/janus+0x4a2062)
    #1 0x7f577c661ef0 in g_malloc0 ../../../glib/gmem.c:132:13
    #2 0x646676 in janus_transport_session_create /home/atoppi/src/janus-gateway/transports/transport.c:25:32
    #3 0x7f576c1341c2 in janus_websockets_common_callback /home/atoppi/src/janus-gateway/transports/janus_websockets.c:1329:20
    #4 0x7f576c13351c in janus_websockets_callback /home/atoppi/src/janus-gateway/transports/janus_websockets.c:1591:9
    #5 0x7f576c0c0eb2 in lws_server_init_wsi_for_ws /home/atoppi/src/libwebsockets/lib/roles/ws/ops-ws.c:855:7
    #6 0x7f576c0c6e80 in lws_process_ws_upgrade2 /home/atoppi/src/libwebsockets/lib/roles/ws/server-ws.c:405:6
    #7 0x7f576c0c733c in lws_process_ws_upgrade /home/atoppi/src/libwebsockets/lib/roles/ws/server-ws.c:634:9
    #8 0x7f576c0b825b in lws_handshake_server /home/atoppi/src/libwebsockets/lib/roles/http/server/server.c:2284:7
    #9 0x7f576c0bdf62 in lws_read_h1 /home/atoppi/src/libwebsockets/lib/roles/h1/ops-h1.c:78:7
    #10 0x7f576c0be6ef in lws_h1_server_socket_service /home/atoppi/src/libwebsockets/lib/roles/h1/ops-h1.c:417:8
    #11 0x7f576c0bead7 in rops_handle_POLLIN_h1 /home/atoppi/src/libwebsockets/lib/roles/h1/ops-h1.c:641:7
    #12 0x7f576c0a90db in lws_service_fd_tsi /home/atoppi/src/libwebsockets/lib/core-net/service.c:719:24
    #13 0x7f576c08b3a2 in _lws_plat_service_forced_tsi /home/atoppi/src/libwebsockets/lib/plat/unix/unix-service.c:49:7
    #14 0x7f576c08b7a5 in _lws_plat_service_tsi /home/atoppi/src/libwebsockets/lib/plat/unix/unix-service.c:207:6
    #15 0x7f576c08b80c in lws_plat_service /home/atoppi/src/libwebsockets/lib/plat/unix/unix-service.c:221:9
    #16 0x7f576c0a927d in lws_service /home/atoppi/src/libwebsockets/lib/core-net/service.c:788:6
    #17 0x7f576c12f4e6 in janus_websockets_thread /home/atoppi/src/janus-gateway/transports/janus_websockets.c:1240:3
    #18 0x7f577c685ad0 in g_thread_proxy ../../../glib/gthread.c:807:20
    #19 0x7f577bf9e608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477:8
    #20 0x7f577be9f292 in clone /build/glibc-eX1tMB/glibc-2.31/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95

It is the result of:

• enabling session reclaim
• establish a session with a backend
• closing janus while a session was active

So yeah maybe we could fix something to avoid this unpleasant leak report but it's not clear if this might be an issue in the long run.

For example I'd like to know what happens if the session is going to be reclaimed: will the "leak" increase?
It would be interesting to understand also what happened on Janus when memory consumption seemed to increase (e.g. backend starting / reconnecting / rebooting?).

[lminiero]

I don't think this needs fixing: if the session hasn't been destroyed (and the reclaim increases the time it lives), then it will leak and it's normal. We do cleanup sessions at shutdown but some may still be there. It would be an issue if during the Janus lifetime a session ended and the reclaim timed out too, but resources were not cleared, which from what I understood is not what's happening here.

[mirkobrankovic]

Yeah, I agree.
I will fix it locally by removing the reclaim session, since we need it only in rare "local network problems" cases, which should not happen that often.
You guys know better internally what is best for Janus as session/user approach.

[lminiero]

No need to close, actually, I was just discussing with @atoppi that there may be a better way of cleaning up sessions at shutdown, which apparently we're not doing exactly as I remembered we did. It is lower priority (since leaks at shutdown are less of an issue), but worth keeping this issue open as a reminder. I'll let you know when there's a PR to test, thanks for bringing this to our attention!

[atoppi]

Besides that enhancement on the shutdown operations, it's still unclear the root of the potential leak shown in the graph.
It's leaking more than 1 GB in ~7 days, that is not something to underestimate.
@mirkobrankovic

1. Could you please share another leak sanitizer report after observing a memory leak similar to the one into the graph?
2. Is that machine only hosting janus ? Could the leak be due to other processes / vm ?
3. Quoting myself

It would be interesting to understand also what happened on Janus when memory consumption seemed to increase (e.g. backend starting / reconnecting / rebooting?).

[lminiero]

If Janus was compiled with libasan support, the memory increasing may be because of that (libasan will keep info on all allocations in memory to know about leaks, and so will never stop growing).

[mirkobrankovic]

The signaling backed logic didn't change, since Janus 0.7.4 running on Ubuntu16.
The leak started when I added 0.10.10 janus on Debian10, (which included newer libwebsockets and libnice), so it is production bineries not compiled with libasan

[mirkobrankovic]

It is deferentially only Janus using that much, now that you said it, maybe with simple use case I did, I didn't trigger the loss.

I do have a JS script pooling Admin Ws for data, maybe I'm not cleaning that one correctly even.
Apr 7 17:07:10 vw364 janus[5064]: [Wed Apr 7 17:07:10 2021] [AdminWSS-0x7f95cf30eb40] Destroying WebSocket client

[atoppi]

@mirkobrankovic so did you manage to identify a critical use case that triggers the issue ?

[mirkobrankovic]

no I tried different scenarios but without reclaim session and no leak so far, i'll give it a bit more try with that setting again

[mirkobrankovic]

@atoppi tonight I will remove session reclaim setting and see if it will make a difference in production

[mirkobrankovic]

I guess I didn't hit the problem with my tests, I see even after turning off reclaim session memory is going down (enabled zabbix at 9:20AM)

The 3 stable hosts are running 0.7.4 version

[atoppi]

@mirkobrankovic
Did the sanitizer report something ?
What happened between 9:20 and 11:00 ?
I find suspicious that the slope started exactly when the zabbix agent has been launched. Have you integrated zabbix with some Janus API ?

[mirkobrankovic]

Yes, zabbix agent is running all the time, there is one check that it is pooling from Janus admin api (number of handles of all sessions), js script run by nodejs, ws connection to admin API.
But the drop started at 9:20 because that was the time I enabled zabbix checks on the host it self, because the maintenance ppl forgot to enable it completely, so there was no data coming in.
Never the less, I disabled this admin check on one host to see if it will make the difference.

[lminiero]

Are event handlers enabled too, by the way?

[mirkobrankovic]

@lminiero yes indeed,
janus.eventhandler.gelfevh
and
janus.eventhandler.sampleevh.jcfg to localhost:8080 with currently no listener (meant for Hepic/Homer Agent)

[mirkobrankovic]

@atoppi yes will do, fixed 3/4 of them, but i'm not sure about:
#2 0x7fddd5d2e40b in janus_videoroom_handler plugins/janus_videoroom.c:6428

[atoppi]

what version of janus is that ?

[mirkobrankovic]

latest master,
commit 216d70c (HEAD -> master, origin/master, origin/HEAD)

[atoppi]

that line does not seem to match any malloc

janus-gateway/plugins/janus_videoroom.c

Line 6428 in 216d70c

if(videoroom->require_pvtid) {

[mirkobrankovic]

yeah, I get the same line, which confused me :/
I'll see if I can repeat that one. Regarding the original problem, I fixed direct leaks in Gelf, but I still have indirect leaks in events.c, specifically:
https://github.com/meetecho/janus-gateway/blob/master/events.c#L305
Then I tried to disable all other event handlers (sample and ws) to have only one and avoid json_deep_copy , but it leads me tho new ones:

=================================================================
==739354==ERROR: LeakSanitizer: detected memory leaks

Indirect leak of 1024 byte(s) in 1 object(s) allocated from:
    #0 0x7f7fa12503cf in __interceptor_malloc (/lib64/libasan.so.6+0xab3cf)
    #1 0x7f7fa0ddcbe9  (/lib64/libjansson.so.4+0x5be9)
    #2 0x7f7fa0ddecf6 in json_object_set_new_nocheck (/lib64/libjansson.so.4+0x7cf6)
    #3 0x4c2e6e in janus_info /home/mirkob/github/janus-gateway/janus.c:396
    #4 0x50e2bb in main /home/mirkob/github/janus-gateway/janus.c:5484
    #5 0x7f7fa04201e1 in __libc_start_main (/lib64/libc.so.6+0x281e1)
    #6 0x40faad in _start (/opt/janus/bin/janus+0x40faad)

not sure how serious those 2 indirect leaks can be ...

[atoppi]

@mirkobrankovic are you compiling with -Og ?

[atoppi]

==739354==ERROR: LeakSanitizer: detected memory leaks

Indirect leak of 1024 byte(s) in 1 object(s) allocated from:
    #0 0x7f7fa12503cf in __interceptor_malloc (/lib64/libasan.so.6+0xab3cf)
    #1 0x7f7fa0ddcbe9  (/lib64/libjansson.so.4+0x5be9)
    #2 0x7f7fa0ddecf6 in json_object_set_new_nocheck (/lib64/libjansson.so.4+0x7cf6)
    #3 0x4c2e6e in janus_info /home/mirkob/github/janus-gateway/janus.c:396
    #4 0x50e2bb in main /home/mirkob/github/janus-gateway/janus.c:5484
    #5 0x7f7fa04201e1 in __libc_start_main (/lib64/libc.so.6+0x281e1)
    #6 0x40faad in _start (/opt/janus/bin/janus+0x40faad)

This one seems to be triggered by the notification of a started instance to the event handlers.

[mirkobrankovic]

I used the docs example:
CFLAGS="-O1 -g3 -ggdb3 -fno-omit-frame-pointer -fsanitize=address -fno-sanitize-recover=all -fsanitize-address-use-after-scope" LDFLAGS="-fsanitize=address" ./configure --prefix ...

[atoppi]

Can you try again (make clean, configure make), replacing O1 with Og ?

[mirkobrankovic]

I did and I get these 2 outputs based on how many event handlers I have compiled and enabled (I was testing this):
guint count = g_hash_table_size(eventhandlers);
If I have 3 event handlers, but only gelf has config file and is emitting events, i get this:
https://pastebin.com/z0EzLc9q
json_deep_copy in event.c
if I compile only gelf and disable rest:
https://pastebin.com/DNG1R1be
indirect leaks are 'a bit' different

[mirkobrankovic]

@atoppi let me see, it might be that I didn't json_decref(event). :/

EDIT:
Yeap, silly me :)
got clean exit now :d

[janus] [Mon Apr 12 14:31:14 2021] Leaving GELF Event handler thread
[janus] [Mon Apr 12 14:31:14 2021] JANUS GelfEventHandler plugin destroyed!
Bye!
(base) mirkob@homesweethome ~/github/janus-gateway (master) $ 

Should be all in PR #2634

[mirkobrankovic]

@lminiero and @atoppi thanks a lot for patience and help :D

[atoppi]

Thanks, we'll review it asap.

[lminiero]

with a simple test where I would accept post request and not respond so Janus would log:
[janus] [Fri Apr 9 16:39:10 2021] [ERR] [events/janus_sampleevh.c:janus_sampleevh_handler:755] Couldn't relay event to the backend: Timeout was reached

It did show quite a big leak:

Direct leak of 6431 byte(s) in 1 object(s) allocated from:
    #0 0x7f03ecbff3cf in __interceptor_malloc (/lib64/libasan.so.6+0xab3cf)
    #1 0x7f03ec78cbc0 in json_dumps (/lib64/libjansson.so.4+0x6bc0)

I think this might be "normal", because even though that event may be freed, when you shutdown the server there are still events in the queue that are never sent (the backend is still not reachable) and so may be leaked. One way to check if an event lost for timeout is actually leaked, is to make sure the events server becomes reachable again before closing Janus, so that events not timed out yet are delivered and freed correctly: I'll try and replicate myself to see if I can see a leak in that case.

[mirkobrankovic]

Ok thanks for explanation.
Regarding the original mention for small leak on shutting down when reclaim session was enabled? Do you want to keep this issue open for it? It went in different directions a bit ;)

[lminiero]

Regarding the original mention for small leak on shutting down when reclaim session was enabled? Do you want to keep this issue open for it?

No need. I actually did make some tests with a different approach, but due to the asynchronous nature of some cleanup mechanisms, leaks would happen anyway. I modified the code to tie removing a session from the hashtable to triggering the unref code, which was supposed to lead to a more rigorous cleanup on shutdown as well (since we destroy the table there, it automatically removes all items it contains); this meant that handles would be marked as destroyed as well, but since handles are only cleaned up when their loop thread completes (which may take longer), they wouldn't be removed in time. As such, considering it's neglectible, I'm not particularly interested in shutdown at the moment.

[mirkobrankovic]

Fair points

[mirkobrankovic]

Just to confim it is fixed.
I just replaced .so and .la of Gelfevh till new tag rolls out, then a proper build will follow :)