[kamailio] debugger: kamailio freezes when dynamically setting module level(using fifo/rpc), if the module level is not previously set in config file: ```modparam("debugger", "mod_level", "core=2")``` (#463)
This **is not** happening when setting the module facility, for the above, same conditions. This **is** happening also before pull-request [1] using "kamcmd dbg.mod_level core 1". After some debugging I've noticed that this **is** happening when trying to set a level for a module name whose ```idx = hid&(_dbg_mod_table_size-1);``` is even number?! (i.e. module name "core" reduces to an even index); the idx is always in the range ```_dbg_mod_table_size-1``` as it should be.
Trying to solve this, I commented the lock_get/release in ```dbg_set_mod_debug_level()``` and saw it's working; kamailio doesn't freeze anymore. Thus, I tried to refactor the locks in ```struct _dbg_mod_slot``` to be dynamically allocated/deallocated using lock_alloc()/destroy() without success.
I'm out of ideas. Do you have any idea what might lead to this strange deadlock?
[1] https://github.com/kamailio/kamailio/pull/462
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463
Also I've been comparing the lock_get()/release() for level vs facility without seeing any differences. But maybe I'm missing something.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169315634
Can you attach with gdb to the locked process (probably the ctl handler) and get a backtrace from it?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169326844
Sorry, I overlooked gdb: (gdb) bt #0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38 #1 0x00007f600269d47c in futex_get (lock=0x7f5ffe91d748) at ../cfgt/../../parser/../mem/../futexlock.h:121 #2 0x00007f60026a6190 in dbg_get_mod_debug_level (mname=0x797349 "core", mnlen=4, mlevel=0x7ffc8bb3a9fc) at debugger_api.c:1479 #3 0x00000000004752c5 in get_debug_level (mname=0x797349 "core", mnlen=4) at dprint.c:164 #4 0x000000000063fc06 in fm_malloc (qmp=0x7f5ffe699000, size=37, file=0x7f60026b9b34 "debugger: debugger_api.c", func=0x7f60026bae40 <__FUNCTION__.8648> "dbg_set_mod_debug_level", line=1352, mname=0x7f60026b8d3e "debugger") at mem/f_malloc.c:438 #5 0x000000000064633c in fm_shm_malloc (qmp=0x7f5ffe699000, size=37, file=0x7f60026b9b34 "debugger: debugger_api.c", func=0x7f60026bae40 <__FUNCTION__.8648> "dbg_set_mod_debug_level", line=1352, mname=0x7f60026b8d3e "debugger") at mem/f_malloc.c:1088 #6 0x00007f60026a565a in dbg_set_mod_debug_level (mname=0x2aa07e0 "core", mnlen=4, mlevel=0x7ffc8bb3abfc) at debugger_api.c:1352 #7 0x00007f60026a3806 in dbg_rpc_set_mod_level (rpc=0x7f6003616660 <binrpc_callbacks>, ctx=0x7ffc8bb3acd0) at debugger_api.c:999 #8 0x00007f60033d2e77 in process_rpc_req (buf=0x2aa07c4 "\241\003\034\023\212\243\062\221\022dbg.set_mod_level", size=35, bytes_needed=0x7ffc8bb3ade8, sh=0x7ffc8bb3ae10, saved_state=0x2ab07c8) at binrpc_run.c:675 #9 0x00007f6003404253 in handle_stream_read (s_c=0x2aa0790, idx=-1) at io_listener.c:511 #10 0x00007f6003405c8a in handle_io (fm=0x7f6006d84498, events=1, idx=-1) at io_listener.c:706 #11 0x00007f60033fd4df in io_wait_loop_epoll (h=0x7f6003617420 <io_h>, t=10, repeat=0) at ../../io_wait.h:1061 #12 0x00007f60034013c3 in io_listen_loop (fd_no=1, cs_lst=0x2a9e400) at io_listener.c:281 #13 0x00007f60033db58c in mod_child (rank=0) at ctl.c:320 #14 0x00000000005ae1cb in init_mod_child (m=0x7f6006d25060, rank=0) at sr_module.c:915 #15 0x00000000005adee8 in init_mod_child (m=0x7f6006d25660, rank=0) at sr_module.c:912 #16 0x00000000005adee8 in init_mod_child (m=0x7f6006d26d78, rank=0) at sr_module.c:912 #17 0x00000000005adee8 in init_mod_child (m=0x7f6006d272b8, rank=0) at sr_module.c:912 #18 0x00000000005adee8 in init_mod_child (m=0x7f6006d276e8, rank=0) at sr_module.c:912 #19 0x00000000005adee8 in init_mod_child (m=0x7f6006d28328, rank=0) at sr_module.c:912 #20 0x00000000005ae503 in init_child (rank=0) at sr_module.c:941 #21 0x00000000004b34c1 in main_loop () at main.c:1671 #22 0x00000000004b9c4c in main (argc=4, argv=0x7ffc8bb3b9a8) at main.c:2597
The deadlock makes sense. MDBG() in fm_malloc() issues dbg_get_mod_debug_level() which gets the same lock that dbg_set_mod_debug_level() already got.
The first option would be to never use locks for dbg_get_mod_debug_level()(because the list is just iterated through, no list mutations). The other option is to create different get/set locks for level/facility in ```struct _dbg_mod_slot```.
What do you think is the best option?
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169332413
This is a recursive access to the same slot in debugger hash table:
* lock the slot to update its list of items * do shm malloc which does internally a log message which needs to get the value of the log level of an item on that slot
Solutions:
* make the locks reentrant (perhaps the safest in long term) * reorder the sequence of code so the shm malloc is not done under the lock (under lock do only insert/remove of the item, but allocation/free of item must be done outside of lock region)
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169385986
Added fix with the second solution on pull-request #469. Basically tested it and the freeze is not happening anymore. However, the first solution can still be logged as an enhancement issue.
If all is ok I will backport this to 4.X branches.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169605420
I am fine with second solution fix, just needs to be kept in mind that no direct or indirect or direct LOG/DBG statements insides locked regions of debugger hash table.
You can merge and close the related issues on tracker.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#issuecomment-169606442
Closed #463.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/463#event-508105819
-
Daniel-Constantin Mierla -
Stefan Mititelu