[SR-Users] Stale dialogs in database - stale reference

Hey all, I am dealing with a possible race condition in the dialog module. About one call in 50 isn't cleared from the database. I catch the calls by joining the dialog table to my cdr table ( which is generated from acc table ). The call remains in the dialog table in the database. I tested, and I am not hitting the destroy_dlg() function which is called from the unref_dlg_unsafe macro. destroy_dlg() calls the remove_dialog_from_db(). unref_dlg_unsafe is called but the ref counter is still at one. I can see this from my logs : 11:22:55 [20195]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 1 to state 3, due event 3 (ref 2) <== de ringing a repondu 11:22:55 [20172]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 3 to state 4, due event 6 (ref 3) <== answer 11:22:55 [20202]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 4, due event 6 (ref 3) <== answer 11:22:55 [20177]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 4, due event 6 (ref 4) <== answer 11:23:05 [20190]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 5, due event 7 (ref 3) <== BYE, hangup 11:23:05 [20183]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 5 to state 5, due event 7 (ref 5) <== confirm hangup The problem seems to be happening randomly and I can't find any explanation for it. So the number of references never reaches 0, because it never reaches 0, the dialog is not unreferenced : Here is the output from syslog ( grepped with the call hash ) : Feb 26 11:21:41 kamailio-1 /usr/sbin/kamailio[20164]: ERROR: dialog [dlg_hash.c:717]: ref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:21:41 kamailio-1 /usr/sbin/kamailio[20164]: ERROR: dialog [dlg_hash.c:737]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 5, due event 7 (ref 3) Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:737]: ref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 2 -> 2 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20214]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20170]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:48 kamailio-1 /usr/sbin/kamailio[20170]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:53 kamailio-1 /usr/sbin/kamailio[20216]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:53 kamailio-1 /usr/sbin/kamailio[20216]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 2 -> 0 Feb 26 11:22:53 kamailio-1 /usr/sbin/kamailio[20216]: ERROR: dialog [dlg_hash.c:757]: ref <=0 for dialog 0x7fab27f4aa88 Feb 26 11:22:53 kamailio-1 /usr/sbin/kamailio[20216]: ERROR: dialog [dlg_hash.c:317]: destroying dialog 0x7fab27f4aa88 (ref 0) Feb 26 11:22:53 kamailio-1 /usr/sbin/kamailio[20216]: ERROR: dialog [dlg_hash.c:333]: removed timer for dlg 0x7fab27f4aa88 [7298:10958] with clid &#39;13b951b67f2704d51d25cf643b3469d1(a)pbx.omnity.biz&#39; and tags 'as3a8e0df2' 'as4c79d466' Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_hash.c:717]: ref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_cb.c:230]: dialog=0x7fab27f4aa88 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_hash.c:737]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20208]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 1 to state 3, due event 3 (ref 2) Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_handlers.c:484]: dialog 0x7fab27f4aa88 confirmed (ACK pending) Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:737]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_cb.c:256]: dialog=0x7fab27f4aa88, type=8 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20174]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20174]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20195]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20178]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20178]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20172]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20172]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 3 to state 4, due event 6 (ref 3) Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20172]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20172]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20172]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 4, due event 6 (ref 3) Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_cb.c:256]: dialog=0x7fab27f4aa88, type=32 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 4, due event 6 (ref 4) Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_cb.c:256]: dialog=0x7fab27f4aa88, type=32 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20202]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:22:55 kamailio-1 /usr/sbin/kamailio[20177]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 3 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 4 to state 5, due event 7 (ref 3) Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:737]: ref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_cb.c:256]: dialog=0x7fab27f4aa88, type=64 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20183]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 5 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20183]: ERROR: dialog [dlg_hash.c:944]: dialog 0x7fab27f4aa88 changed from state 5 to state 5, due event 7 (ref 5) Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20183]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20183]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 5 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20183]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 4 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 2 -> 2 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:590]: ref dlg 0x7fab27f4aa88 with 1 -> 2 Feb 26 11:23:05 kamailio-1 /usr/sbin/kamailio[20190]: ERROR: dialog [dlg_hash.c:757]: unref dlg 0x7fab27f4aa88 with 1 -> 1 You can see the last refence is never removed, so the dialog isn't destroyed. Here is the end of a healthy dialog : Feb 26 08:03:00 kamailio-1 /usr/sbin/kamailio[4668]: ERROR: dialog [dlg_hash.c:753]: unref dlg 0x7f74db910e60 with 2 -> 0 Feb 26 08:03:00 kamailio-1 /usr/sbin/kamailio[4668]: ERROR: dialog [dlg_hash.c:753]: ref <=0 for dialog 0x7f74db910e60 Feb 26 08:03:00 kamailio-1 /usr/sbin/kamailio[4668]: ERROR: dialog [dlg_hash.c:315]: destroying dialog 0x7f74db910e60 (ref 0) You see it falls to 0 and the dialog is destroyed. So, how do I debug this ? Should I maybe be posting to sr-dev ? How do I determine who is incrementing the counter without decrementing it? What information do I need to continue with this problem? Thanks! David ps I used perl pie to replace LM_DBG with LM_ERROR in modules_k/dialog/* version: kamailio 3.3.2 (x86_64/linux) flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 09:17:03 Oct 18 2012 with gcc 4.4.3