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@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@192.168.2.2:5080 callid:: c3e141c7-a61270ac@192.168.2.93 from:: uri=sip:0026998D2646-1@192.168.2.2 tag=df62070b4614cc38o0 to:: "Ovidiu Sas" uri=sip:248@192.168.2.2 tag=bk2bk.82.426 cseq:: caller=101 callee=1 contact:: caller=sip:0026998D2646-1@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@192.168.2.20 tag=85264a8f8cfcee6787f3406feb27d2b7 to:: uri=sip:248@192.168.2.20 tag=as07119f07 cseq:: caller=104 callee=1 contact:: caller=sip:192.168.2.2:5080 callee=sip:248@192.168.2.20:5060 send_sock:: 192.168.2.2 leg:: 0 tag=as07119f07 cseq=103 contact=sip:248@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.2:5080 callid:: c3e141c7-a61270ac@192.168.2.93 from:: uri=sip:0026998D2646-1@192.168.2.2 tag=df62070b4614cc38o0 to:: "Ovidiu Sas" uri=sip:248@192.168.2.2 tag=bk2bk.82.426 cseq:: caller=101 callee=1 contact:: caller=sip:0026998D2646-1@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@192.168.2.20 tag=85264a8f8cfcee6787f3406feb27d2b7 to:: uri=sip:248@192.168.2.20 tag=as07119f07 cseq:: caller=105 callee=1 contact:: caller=sip:192.168.2.2:5080 callee=sip:248@192.168.2.20:5060 send_sock:: 192.168.2.2 leg:: 0 tag=as07119f07 cseq=103 contact=sip:248@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.82.426',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.2:5080 callid:: c3e141c7-a61270ac@192.168.2.93 from:: uri=sip:0026998D2646-1@192.168.2.2 tag=df62070b4614cc38o0 to:: "Ovidiu Sas" uri=sip:248@192.168.2.2 tag=bk2bk.82.426 cseq:: caller=101 callee=1 contact:: caller=sip:0026998D2646-1@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@192.168.2.20 tag=85264a8f8cfcee6787f3406feb27d2b7 to:: uri=sip:248@192.168.2.20 tag=as07119f07 cseq:: caller=105 callee=1 contact:: caller=sip:192.168.2.2:5080 callee=sip:248@192.168.2.20:5060 send_sock:: 192.168.2.2 leg:: 0 tag=as07119f07 cseq=103 contact=sip:248@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@192.168.2.20>',e1_from='sip:osas@192.168.2.20',e1_key='bk2bk.421.328',e2_type=1,e2_sid='',e2_to='<sip:248@192.168.2.20>',e2_from='sip:osas@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@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@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 _______________________________________________ Devel mailing list Devel@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/devel