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

David kamailio.org at spam.lublink.net
Tue Feb 26 19:08:33 CET 2013


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




More information about the sr-users mailing list