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

[David]

Hey,

Not sure if it matters, but the column 'state' stays at '4' even if the 
log says state 5.

David

On 13-02-26 01:08 PM, David wrote:
> 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 '13b951b67f2704d51d25cf643b3469d1 at pbx.omnity.biz' 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
>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users