[OpenSIPS-Devel] All debugs to set a diagnostic of why dialog are not removed in my OpenSIPs 1.5.1 (SIP trace + opensips debug 4 + opensipsctl fifo dlg_list )
Marc Leurent
marc.leurent at vtx-telecom.ch
Mon May 11 11:02:42 CEST 2009
When monitoring a REGISTER dialog, I have found that is creates 2 dialogs, here is an example,
it creates 2 dialogs (first REGISTER / 401 Unauthorized) with dialog 3102:436706855 or 0x2b2cc4ab4b58
and after (REGISTER / 200 OK) with dialog 3102:436706856 or 0x2b2cc4ab52d8
The first one is correctly removed, but not the second one! I have to wait 3 hours before its removal
Here is the second dialog that is not removed:
dialog:: hash=3102:436706856
state:: 3
user_flags:: 0
timestart:: 1242030852
timeout:: 10915
callid:: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
from_uri:: sip:0213115090 at 212.147.46.91
from_tag:: ypyiu
caller_contact:: sip:0213115090 at 194.38.160.113:5070
caller_cseq:: 604
caller_route_set::
caller_bind_addr:: udp:212.147.46.91:5060
to_uri:: sip:0213115090 at 212.147.46.91
to_tag:: as6c579ae5
callee_contact:: sip:0213115090 at 212.147.46.81:5060
callee_cseq:: 604
callee_route_set::
callee_bind_addr:: udp:212.147.46.91:5060
Here is my opensips.log file:
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:build_new_dlg: new dialog 0x2b2cc4ab4b58 (c=jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
,f=sip:0213115097.46.91,t=5090 at 212.147.46.91,ft=ypyiu) on hash 3102
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:populate_leg_info: route_set , contact sip:0213115090 at 194.38.160.113:5070, cseq 603 and bind_
addr udp:212.147060
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:dlg_set_leg_info: set leg 0 for 0x2b2cc4ab4b58: tag=<ypyiu> rr=<> ct=<sip:0213115090 at 194.38.1
60.113:5070> cse
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:link_dlg: ref dlg 0x2b2cc4ab4b58 with 3 -> 3
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
May 11 10:34:12 vp-pro-01 opensips[3265]: DBG:dialog:unref_dlg: unref dlg 0x2b2cc4ab4b58 with 1 -> 2
May 11 10:34:12 vp-pro-01 opensips[3263]: DBG:dialog:next_state_dlg: dialog 0x2b2cc4ab4b58 changed from state 1 to state 5, due event 4
May 11 10:34:12 vp-pro-01 opensips[3263]: DBG:dialog:dlg_onreply: dialog 0x2b2cc4ab4b58 failed (negative reply)
May 11 10:34:12 vp-pro-01 opensips[3263]: DBG:dialog:unref_dlg: unref dlg 0x2b2cc4ab4b58 with 1 -> 1
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:build_new_dlg: new dialog 0x2b2cc4ab52d8 (c=jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
,f=sip:0213115097.46.91,t=5090 at 212.147.46.91,ft=ypyiu) on hash 3102
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:populate_leg_info: route_set , contact sip:0213115090 at 194.38.160.113:5070, cseq 604 and bind_
addr udp:212.147060
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:dlg_set_leg_info: set leg 0 for 0x2b2cc4ab52d8: tag=<ypyiu> rr=<> ct=<sip:0213115090 at 194.38.1
60.113:5070> cse
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:link_dlg: ref dlg 0x2b2cc4ab52d8 with 3 -> 3
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
May 11 10:34:12 vp-pro-01 opensips[3270]: DBG:dialog:unref_dlg: unref dlg 0x2b2cc4ab52d8 with 1 -> 2
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:next_state_dlg: dialog 0x2b2cc4ab52d8 changed from state 1 to state 3, due event 3
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:dlg_onreply: dialog 0x2b2cc4ab52d8 confirmed
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:dlg_onreply: 0x2b2cc4ab52d8 totag in rpl is <as6c579ae5> (10)
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:populate_leg_info: route_set , contact sip:0213115090 at 212.147.46.81:5060, cseq 604 and bind_a
ddr udp:212.147.60
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:dlg_set_leg_info: set leg 1 for 0x2b2cc4ab52d8: tag=<as6c579ae5> rr=<> ct=<sip:0213115090 at 212
.147.46.81:5060>04>
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0x2b2cc4ab5310 for 10915
May 11 10:34:12 vp-pro-01 opensips[3269]: DBG:dialog:ref_dlg: ref dlg 0x2b2cc4ab52d8 with 1 -> 3
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:next_state_dlg: dialog 0x2b2cc4ab4b58 changed from state 5 to state 5, due event 1
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:unref_dlg: unref dlg 0x2b2cc4ab4b58 with 1 -> 0
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:unref_dlg: ref <=0 for dialog 0x2b2cc4ab4b58
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:destroy_dlg: destroing dialog 0x2b2cc4ab4b58
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x2b2cc4ab4b58 [3102:436706855] with clid 'jjol
rfphvjriywr at leonerne.smarth' and tags 'ypyiu' ''
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:next_state_dlg: unref dlg 0x2b2cc4ab52d8 with 1 -> 2
May 11 10:34:17 vp-pro-01 opensips[3280]: DBG:dialog:next_state_dlg: dialog 0x2b2cc4ab52d8 changed from state 3 to state 3, due event 1
you can see that it try to remove the first dialog twice, so it failed!
And here is my SIP trace:
REGISTER sip:212.147.46.91 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.206:5070;rport;branch=z9hG4bKinxbzijz
Max-Forwards: 70
To: "0213115090" <sip:0213115090 at 212.147.46.91>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 603 REGISTER
Contact: <sip:0213115090 at 192.168.10.206:5070>;expires=1800
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
User-Agent: Twinkle/1.4.2
Content-Length: 0
REGISTER sip:212.147.46.91 SIP/2.0
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.72e970a1>
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bKc85e.d6359375.0
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKinxbzijz
Max-Forwards: 69
To: "0213115090" <sip:0213115090 at 212.147.46.91>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 603 REGISTER
Contact: <sip:0213115090 at 194.38.160.113:5070>;expires=1800
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
User-Agent: Twinkle/1.4.2
Content-Length: 0
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bKc85e.d6359375.0;received=212.147.46.91
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKinxbzijz
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.72e970a1>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 603 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bKc85e.d6359375.0;received=212.147.46.91
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKinxbzijz
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=as6c579ae5
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 603 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="voip", nonce="143f1691"
Content-Length: 0
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKinxbzijz
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=as6c579ae5
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 603 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm="voip", nonce="143f1691"
Content-Length: 0
REGISTER sip:212.147.46.91 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.206:5070;rport;branch=z9hG4bKfmplnebu
Max-Forwards: 70
To: "0213115090" <sip:0213115090 at 212.147.46.91>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 604 REGISTER
Contact: <sip:0213115090 at 192.168.10.206:5070>;expires=1800
Authorization: Digest username="0213115090",realm="voip",nonce="143f1691",uri="sip:212.147.46.91",response="xxxxxxxxxxxxxxx",algorithm=MD5
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
User-Agent: Twinkle/1.4.2
Content-Length: 0
REGISTER sip:212.147.46.91 SIP/2.0
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.82e970a1>
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bK985e.20bbcb63.0
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKfmplnebu
Max-Forwards: 69
To: "0213115090" <sip:0213115090 at 212.147.46.91>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 604 REGISTER
Contact: <sip:0213115090 at 194.38.160.113:5070>;expires=1800
Authorization: Digest username="0213115090",realm="voip",nonce="143f1691",uri="sip:212.147.46.91",response="xxxxxxxxxxxxxxx",algorithm=MD5
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
User-Agent: Twinkle/1.4.2
Content-Length: 0
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bK985e.20bbcb63.0;received=212.147.46.91
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKfmplnebu
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.82e970a1>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 604 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.147.46.91;branch=z9hG4bK985e.20bbcb63.0;received=212.147.46.91
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKfmplnebu
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.82e970a1>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=as6c579ae5
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 604 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 180
Contact: <sip:0213115090 at 194.38.160.113:5070>;expires=180
Date: Mon, 11 May 2009 08:34:12 GMT
Content-Length: 0
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.10.206:5070;received=194.38.160.113;rport=5070;branch=z9hG4bKfmplnebu
Record-Route: <sip:212.147.46.91;lr=on;ftag=ypyiu;did=e1c.82e970a1>
From: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=ypyiu
To: "0213115090" <sip:0213115090 at 212.147.46.91>;tag=as6c579ae5
Call-ID: jjolrfphvjriywr at leonhart.interne.smart-telecom.ch
CSeq: 604 REGISTER
User-Agent: voipua
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 180
Contact: <sip:0213115090 at 212.147.46.81:5060>;expires=180
Date: Mon, 11 May 2009 08:34:12 GMT
Content-Length: 0
-- --
Marc LEURENT
Ingénieur VoIP
DECKPOINT SA
Une société du groupe VTX Telecom
================================================================
Rue Eugène-Marziano 15 - 1227 Les Acacias
http://www.vtx.ch - marc.leurent at vtx-telecom.ch
----------------------------------------------------------------
VTX, votre partenaire telecom proche de vous !
================================================================
Le Monday 11 May 2009 10.21:14 Marc Leurent, vous avez écrit :
> Good morning everybody,
> Thank you for the information!!
>
> So my first problem is that dialogs are built even if I do not call the create_dialog() function or the setflag(4) that I have defined in dialog params..
>
> To answer your question, yes dialogs are being removed, but some of them are not, I think because of reasons below:
>
> Each time I REGISTER:
> If Contact header is used to match the dialog, if I rewrite it because of routing specific architecture in fix_nated_contact();, dialogs won't be removed even if I use modparam("dialog", "dlg_match_mode", 0) ?? Because dialogs are still there after the 200 OK like this dialog for REGISTER:
> dialog:: hash=3917:871117747
> state:: 3
> user_flags:: 0
> timestart:: 1242029446
> timeout:: 11025
> callid:: jjolrfphvjriywr at leonhart.interne
> from_uri:: sip:0213115090 at 212.147.46.91
> from_tag:: pnvkk
> caller_contact:: sip:02131090 at 194.38.160.113:5070
> caller_cseq:: 554
> caller_route_set::
> caller_bind_addr:: udp:212.147.46.91:5060
> to_uri:: sip:0213115090 at 212.147.46.91
> to_tag:: as54366440
> callee_contact:: sip:02131090 at 212.147.46.81:5060
> callee_cseq:: 554
> callee_route_set::
> callee_bind_addr:: udp:212.147.46.91:5060
>
>
> Each time I unregister,I got an error:
> ERROR:dialog:populate_leg_info: bad sip message or missing Contact hdr
> Indeed, my Asterisk servers are responding without a Contact header to unregister, keeping dialog data until timeout
> and I thought dialog module didn't need it for matching the dialog!
>
> Thank you
> ++
>
> -- --
> Marc LEURENT
> lftsy at leurent.eu
>
> Le Saturday 09 May 2009 10.59:18 Bogdan-Andrei Iancu, vous avez écrit :
> > Hi Marc,
> >
> > It is normal to increase as it is an absolute timestamp - see my prev
> > email on this thread.
> >
> > Regarding the shm mem - do you see the dialogs actually being removed?
> >
> > Regards,
> > Bogdan
> >
> > Marc Leurent wrote:
> > > Sorry for the 3rd email.. but I think it's interesting, because the dialog timeout of my transactions seems to increase with OpenSIPs uptime!
> > > So my shm memory increase all the time. Does any one have the same problem with OpenSIPs 1.5.1?
> > > Thanks
> > >
> > > opensipsctl fifo dlg_list | grep timeout | sort -nr
> > > timeout:: 20395
> > > timeout:: 20340
> > > timeout:: 20285
> > > timeout:: 20230
> > > timeout:: 20175
> > > timeout:: 20120
> > > timeout:: 20064
> > > timeout:: 20009
> > > timeout:: 19954
> > > timeout:: 19899
> > > ...
> > >
> > > and just after
> > > opensipsctl fifo dlg_list | grep timeout | sort -nr
> > > timeout:: 20450
> > > timeout:: 20395
> > > timeout:: 20340
> > > timeout:: 20285
> > > timeout:: 20230
> > > timeout:: 20175
> > > timeout:: 20120
> > > timeout:: 20064
> > > timeout:: 20009
> > > timeout:: 19954
> > > timeout:: 19899
> > > ...
> > >
> > > PS: I'm using
> > > opensips -V
> > > version: opensips 1.5.1-notls (x86_64/linux)
> > > flags: STATS: Off, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
> > > ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
> > > poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
> > > svnrevision: unknown
> > > @(#) $Id: main.c 5469 2009-03-18 12:43:10Z bogdan_iancu $
> > > main.c compiled on 19:03:00 Apr 30 2009 with gcc 4.1.2
> > >
> > >
> > > Le Friday 08 May 2009 13.06:18 Marc Leurent, vous avez écrit :
> > >
> > >> Hello all, I have juste a small question about the dialog module, I have set the parameters below for OpenSIPs dialog module with a "default_timeout", to 3 hours,
> > >>
> > >> # ----- dialog params -----
> > >> modparam("dialog", "enable_stats", 1) # If the statistics support should be enabled or not.
> > >> #modparam("dialog", "hash_size", 4096) # The size of the hash table internally used to keep the dialogs.
> > >> modparam("dialog", "rr_param", "did") # Name of the Record-Route parameter to be added with the dialog cookie.
> > >> modparam("dialog", "dlg_flag", 4) # Flag to be used for marking if a dialog should be constructed for the current request.
> > >> #modparam("dialog", "buy_on_timeout_flag", 6) # Message falg to be set if you want the dialog module to automatically send BYE requests (in both directions) when the dialog give timeout.
> > >> #modparam("dialog", "timeout_avp", "$avp(i:10)") # The specification of an AVP to contain a custom timeout (in seconds) for the dialog.
> > >> modparam("dialog", "default_timeout", 10800) # The default dialog timeout (in seconds) if no custom one is set.
> > >> #modparam("dialog", "dlg_extra_hdrs", "Hint: credit expired\r\n") # A string containing the extra headers to be added in the requests generated
> > >> modparam("dialog", "dlg_match_mode", 0) # The match is done exclusively based on DID;
> > >> modparam("dialog", "db_url", "mysql://opensips:Uwefwefwefo3J@localhost/opensips")
> > >> modparam("dialog", "db_mode", 1) # Describe how to push into the DB the dialogs' information from memory.
> > >> modparam("dialog", "db_update_period", 30) # The interval (seconds) at which to update dialogs' information if you chose to store.
> > >> #modparam("dialog", "profiles_with_value", "caller ; my_profile") # List of names for profiles with values.
> > >> #modparam("dialog", "profiles_no_value", "inbound ; outbound") # List of names for profiles without values.
> > >>
> > >> but I have some dialogs that have a superior timeout like this one..
> > >> Have you got any idea how to see where this timeout is defined and how to force it to a lower value!
> > >> Because of this, I reach my "snmpstats", "dlg_minor_threshold", 900 very quickly
> > >> Thanks!
> > >>
> > >> dialog:: hash=1768:1584216798
> > >> state:: 3
> > >> user_flags:: 0
> > >> timestart:: 1241777705
> > >> timeout:: 16267
> > >> callid:: zaltktgtpqzdqvo at leonhart.interne
> > >> from_uri:: sip:0213115090 at 212.147.46.91
> > >> from_tag:: ooctt
> > >> caller_contact:: sip:0213115090 at 194.38.160.113:5070
> > >> caller_cseq:: 960
> > >> caller_route_set::
> > >> caller_bind_addr:: udp:212.147.46.91:5060
> > >> to_uri:: sip:0213115090 at 212.147.46.91
> > >> to_tag:: as79ae919b
> > >> callee_contact:: sip:0213115090 at 212.147.46.81:5060
> > >> callee_cseq:: 960
> > >> callee_route_set::
> > >> callee_bind_addr:: udp:212.147.46.91:5060
> > >>
> > >>
> > >>
> > >
> > >
> > >
> >
>
>
>
> _______________________________________________
> Devel mailing list
> Devel at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
>
More information about the Devel
mailing list