[OpenSIPS-Devel] [ opensips-Bugs-3317402 ] b2b calls out of sync after server restart
SourceForge.net
noreply at sourceforge.net
Fri Jun 17 12:42:24 CEST 2011
Bugs item #3317402, was opened at 2011-06-16 19:53
Message generated for change (Comment added) made by anca_vamanu
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3317402&group_id=232389
Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: trunk
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Ovidiu Sas (osas)
Assigned to: Nobody/Anonymous (nobody)
Summary: b2b calls out of sync after server restart
Initial Comment:
If a server is restarted while a b2b call is active, the b2b call is restored from the db.
The issue is that subsequent in-dialog requests are having the Cseq reseted and this is causing rejections from the far end.
How to reproduce:
- initiate a b2b call,
- answer the b2b call,
- send a reINVITE,
- restart opensips,
- send a reINVITE from one of the participants and check the CSeq number
It seems that the CSeq fields are not updated into the db.
Regards,
Ovidiu Sas
----------------------------------------------------------------------
>Comment By: Anca Vamanu (anca_vamanu)
Date: 2011-06-17 13:42
Message:
Hello Ovidiu,
The first thing that I noticed in your sql traces is that only one dialog
is updated. The thing is that in the way the WRITE_THROUGH mode was working
until today, the updates in db for a dialog were done only when a request
or reply was received. It was assumed that replies sent out don't change
state and that requests sent out will eventually receive a reply and the
state will be save then. However this is indeed not that accurate. This is
the reason why today I committed a modification. I have also called the
update function where requests or replies are sent out, with an efficiency
check to make sure that you don't update in the same processing sequence
the same dialog twice. If you can please take the new code and test.
However, apart from this observation the traces don't really show what you
suspected. First, to make it clear - the reInvite is received in this
dialog: "callid:: c3e141c7-a61270ac at 192.168.2.93" ? For this dialog the
cseq doesn't changes neither in memory. And I have now checked, the b2b
doesn't update the caller cseq never. Because it doesn't actually need that
cseq as no cseq validation is preformed. I wrote a few lines to make a cseq
check and to update the cseq in prescript_f function, but then realized
that the cseq must be updated also when PRACK is received ( and now for
PRACK the dialog is not even searched - 200OK is sent directly). And since
I don't have the time and means to test now, I have not completed the
patch. If you are willing to work on the PRACK part I can give you the
partial patch that I have now.
Apart from this, you said in the initial comment that the in-dialog
requests after restart are rejected by far end - so it actually seems there
is a problem with updating the local_cseq. Please try the patch that I
committed today that updates the dialog more often and say if this problem
appears still.
Regards,
Anca
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2011-06-17 00:59
Message:
Here's what we have in memory compared with what is saved on db.
<call answered (in conversation>
$ opensipsctl fifo b2be_list
dlg:: 426 param=561.0 state=5 last_invite_cseq=101 last_method=0
last_reply_code=200 db_flag=2
ruri:: sip:248 at 192.168.2.2:5080
callid:: c3e141c7-a61270ac at 192.168.2.93
from:: uri=sip:0026998D2646-1 at 192.168.2.2 tag=df62070b4614cc38o0
to:: "Ovidiu Sas" uri=sip:248 at 192.168.2.2 tag=bk2bk.82.426
cseq:: caller=101 callee=1
contact:: caller=sip:0026998D2646-1 at 192.168.2.93:5060
callee=sip:192.168.2.2:5080
send_sock:: 192.168.2.2
dlg:: 5416268 param=561.0 state=5 last_invite_cseq=104 last_method=4
db_flag=2
callid:: bk2bk.49.5416268
from:: "Ovidiu Sas PBX " uri=sip:osas at 192.168.2.20
tag=85264a8f8cfcee6787f3406feb27d2b7
to:: uri=sip:248 at 192.168.2.20 tag=as07119f07
cseq:: caller=104 callee=1
contact:: caller=sip:192.168.2.2:5080
callee=sip:248 at 192.168.2.20:5060
send_sock:: 192.168.2.2
leg:: 0 tag=as07119f07 cseq=103 contact=sip:248 at 192.168.2.20:5060
<reINVITE (hold) received>
110616 18:21:24 64478 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64478 Query update b2b_entities set
state=6,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='df62070b4614cc38o0' AND tag1='bk2bk.82.426' AND
callid='c3e141c7-a61270ac at 192.168.2.93'
64477 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64478 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64478 Query update b2b_entities set
state=5,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='df62070b4614cc38o0' AND tag1='bk2bk.82.426' AND
callid='c3e141c7-a61270ac at 192.168.2.93'
and in memory we have:
$ opensipsctl fifo b2be_list
dlg:: 426 param=561.0 state=5 last_invite_cseq=101 last_method=0
last_reply_code=200 db_flag=2
ruri:: sip:248 at 192.168.2.2:5080
callid:: c3e141c7-a61270ac at 192.168.2.93
from:: uri=sip:0026998D2646-1 at 192.168.2.2 tag=df62070b4614cc38o0
to:: "Ovidiu Sas" uri=sip:248 at 192.168.2.2 tag=bk2bk.82.426
cseq:: caller=101 callee=1
contact:: caller=sip:0026998D2646-1 at 192.168.2.93:5060
callee=sip:192.168.2.2:5080
send_sock:: 192.168.2.2
dlg:: 5416268 param=561.0 state=5 last_invite_cseq=105 last_method=4
db_flag=2
callid:: bk2bk.49.5416268
from:: "Ovidiu Sas PBX " uri=sip:osas at 192.168.2.20
tag=85264a8f8cfcee6787f3406feb27d2b7
to:: uri=sip:248 at 192.168.2.20 tag=as07119f07
cseq:: caller=105 callee=1
contact:: caller=sip:192.168.2.2:5080
callee=sip:248 at 192.168.2.20:5060
send_sock:: 192.168.2.2
leg:: 0 tag=as07119f07 cseq=103 contact=sip:248 at 192.168.2.20:5060
<reINVITE(resume) received>
110616 18:21:45 64477 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64477 Query update b2b_entities set
state=6,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='df62070b4614cc38o0' AND tag1='bk2bk.82.426' AND
callid='c3e141c7-a61270ac at 192.168.2.93'
64478 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64477 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298856,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.5416268'
where si_key='561.0'
64477 Query update b2b_entities set
state=5,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='df62070b4614cc38o0' AND tag1='bk2bk.82.426' AND
callid='c3e141c7-a61270ac at 192.168.2.93'
and in memory we have:
$ opensipsctl fifo b2be_list
dlg:: 426 param=561.0 state=5 last_invite_cseq=101 last_method=0
last_reply_code=200 db_flag=2
ruri:: sip:248 at 192.168.2.2:5080
callid:: c3e141c7-a61270ac at 192.168.2.93
from:: uri=sip:0026998D2646-1 at 192.168.2.2 tag=df62070b4614cc38o0
to:: "Ovidiu Sas" uri=sip:248 at 192.168.2.2 tag=bk2bk.82.426
cseq:: caller=101 callee=1
contact:: caller=sip:0026998D2646-1 at 192.168.2.93:5060
callee=sip:192.168.2.2:5080
send_sock:: 192.168.2.2
dlg:: 5416268 param=561.0 state=5 last_invite_cseq=105 last_method=4
db_flag=2
callid:: bk2bk.49.5416268
from:: "Ovidiu Sas PBX " uri=sip:osas at 192.168.2.20
tag=85264a8f8cfcee6787f3406feb27d2b7
to:: uri=sip:248 at 192.168.2.20 tag=as07119f07
cseq:: caller=105 callee=1
contact:: caller=sip:192.168.2.2:5080
callee=sip:248 at 192.168.2.20:5060
send_sock:: 192.168.2.2
leg:: 0 tag=as07119f07 cseq=103 contact=sip:248 at 192.168.2.20:5060
Regards,
Ovidiu Sas
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2011-06-17 00:52
Message:
Hello Anca,
Here are the SQL logs for:
reINVITE (hold):
110616 18:07:38 64367 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298047,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64367 Query update b2b_entities set
state=6,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='43df5fc486f6e51ao0' AND tag1='bk2bk.421.328' AND
callid='8bd9ac8c-1e6fbef2 at 192.168.2.93'
110616 18:07:39 64366 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298048,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64368 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298048,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64368 Query update b2b_entities set
state=5,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='43df5fc486f6e51ao0' AND tag1='bk2bk.421.328' AND
callid='8bd9ac8c-1e6fbef2 at 192.168.2.93'
reINVITE (active):
110616 18:07:49 64367 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298047,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64367 Query update b2b_entities set
state=6,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='43df5fc486f6e51ao0' AND tag1='bk2bk.421.328' AND
callid='8bd9ac8c-1e6fbef2 at 192.168.2.93'
64368 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298047,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64366 Query update b2b_logic set
sstate=-3,next_sstate=0,lifetime=1308298047,e1_type=0,e1_sid='',e1_to='<sip:248 at 192.168.2.20>',e1_from='sip:osas at 192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248 at 192.168.2.20>',e2_from='sip:osas at 192.168.2.20',e2_key='bk2bk.49.3932322'
where si_key='561.0'
64366 Query update b2b_entities set
state=5,cseq0=101,cseq1=1,lm=0,lrc=200,lic=101,contact0='sip:0026998D2646-1 at 192.168.2.93:5060',contact1='sip:192.168.2.2:5080'
where type=0 AND tag0='43df5fc486f6e51ao0' AND tag1='bk2bk.421.328' AND
callid='8bd9ac8c-1e6fbef2 at 192.168.2.93'
Regards,
Ovidiu Sas
----------------------------------------------------------------------
Comment By: Anca Vamanu (anca_vamanu)
Date: 2011-06-16 22:50
Message:
Hi Ovidiu,
The code shows that the update function is called, but maybe there is
something with the query. Can you please investigate by watching the sql
query traces in your sql server?
Regards,
Anca
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2011-06-16 21:06
Message:
Hello Anca,
I uploaded a file wilth the b2b logs and the SIP requests.
Thanks,
Ovidiu
----------------------------------------------------------------------
Comment By: Anca Vamanu (anca_vamanu)
Date: 2011-06-16 20:51
Message:
Hi Ovidiu,
The db update function in b2b_entities modules does update the cseq -
check b2be_db_update function. And for reInvite this function should be
called by the b2b_prescript_f function. Please check in the logs which are
the messages printed for the processing of the reInvite ( note that in the
b2be_db_update a DBG is printed starting with b2be_db_update:UPDATED )
Regards,
Anca
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3317402&group_id=232389
More information about the Devel
mailing list