#387 b2b calls out of sync after server restart

trunk
closed-fixed
nobody
modules (454)
5
2011-06-17
2011-06-16
Ovidiu Sas
No

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

Discussion

  • Anca Vamanu
    Anca Vamanu
    2011-06-16

    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

     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-16

    b2b logs

     
    Attachments
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-16

    Hello Anca,

    I uploaded a file wilth the b2b logs and the SIP requests.

    Thanks,
    Ovidiu

     
  • Anca Vamanu
    Anca Vamanu
    2011-06-16

    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

     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-16

    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

     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-16

    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

     
  • Anca Vamanu
    Anca Vamanu
    2011-06-17

    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

     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-17

    • status: open --> open-fixed
     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-17

    Hello Anca,

    I noticed that only one dialog was updated in the trace (it is true that I did not mentioned this in the latest post) and you confirmed that.
    The fix is working ok.

    I don't know if we really need to do something about PRACK, because the PRACK makes sense only during alerting, and in alerting state, calls don't survive a restart (the transaction is lost).

    If you think that is worth doing something for PRACK, I can try to validate your patch. Please send me the patch privately and I will try to test it for you and we will continue the PRACK discussion on the mailing list.

    Thanks,
    Ovidiu

     
  • Ovidiu Sas
    Ovidiu Sas
    2011-06-17

    • status: open-fixed --> closed-fixed
     
  • Anca Vamanu
    Anca Vamanu
    2011-06-20

    Hi Ovidiu,

    Great that the patch works, thank you for testing.

    For the other issue with checking cseq, I was saying that we need to updated the saved cseq when PRACK is received also - because it is my understanding that it actually updates the remote cseq in that dialog. But it is indeed possible to ignore this and start updating only after the state is confirmed. I will send you the patch to validate it and if ok, I will commit it.

    Regards,
    Anca