Opensips 1.6.2 to 1.6.3 SST module question

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

Opensips 1.6.2 to 1.6.3 SST module question

k1028
I am not a expert on this but would like to get some understand what is the problem with my configuration.

I am getting call drop caused by the STT module on 1.6.3 but not on 1.6.2 every 180 seconds if I set modparam("sst", "min_se", 180).

This is my configuration
# ----- Dialog params -----
modparam("dialog", "dlg_flag", 4)                                      
modparam("dialog", "timeout_avp", "$avp(i:10)")
modparam("dialog", "bye_on_timeout_flag", 14)
modparam("dialog", "db_mode", 1)

# ----- SST params -----
modparam("sst", "timeout_avp", "$avp(i:10)")
modparam("sst", "sst_flag", 5)
modparam("sst", "min_se", 180) # Must be >= 90

if (is_method("INVITE")) {
     if (sstCheckMin("1")) {
          xlog("L_ERR", "Session Timer Too Small.\n\n");
          exit;
      }
      setflag(4); #Dialog module Flag
      setflag(5); #SST module Flag
      setflag(14); #SST Dialog Timeout Flag
      route(2);
}



Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

Bogdan-Andrei Iancu
Hi,

You mean the call does not get established? or the call is established
but terminated after some time ?

Could you post a SIP trace of such a call ?

Regards,
Bogdan

k1028 wrote:

> I am not a expert on this but would like to get some understand what is the
> problem with my configuration.
>
> I am getting call drop caused by the STT module on 1.6.3 but not on 1.6.2
> every 180 seconds if I set modparam("sst", "min_se", 180).
>
> This is my configuration
> # ----- Dialog params -----
> modparam("dialog", "dlg_flag", 4)                                      
> modparam("dialog", "timeout_avp", "$avp(i:10)")
> modparam("dialog", "bye_on_timeout_flag", 14)
> modparam("dialog", "db_mode", 1)
>
> # ----- SST params -----
> modparam("sst", "timeout_avp", "$avp(i:10)")
> modparam("sst", "sst_flag", 5)
> modparam("sst", "min_se", 180) # Must be >= 90
>
> if (is_method("INVITE")) {
>      if (sstCheckMin("1")) {
>           xlog("L_ERR", "Session Timer Too Small.\n\n");
>           exit;
>       }
>       setflag(4); #Dialog module Flag
>       setflag(5); #SST module Flag
>       setflag(14); #SST Dialog Timeout Flag
>       route(2);
> }
>
>
>
>
>  


--
Bogdan-Andrei Iancu
OpenSIPS Bootcamp
20 - 24 September 2010, Frankfurt, Germany
www.voice-system.ro


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

k1028
I apologized that I wasn't clear enough. The call is established but terminated after some time. I can provide the SIP trace later today. Thank You
Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

k1028
In reply to this post by Bogdan-Andrei Iancu
The call is established but terminated after some time.

Here is the SIP trace from siptrace module and debug 5 from Opensips. There is no BYE in the SIPTrace. Debug 5 from Opensips did show BYE sent to caller and to callee from dialog module.

INVITE sip:1510495xxxx@74.x.x.x. SIP/2.0
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Max-Forwards: 69
Contact: <sip:1111@173.x.x.x:5068>
To: <sip:1510495xxxx@74.x.x.x.>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Type: application/sdp
User-Agent: Idefisk
Content-Length: 220
Session-Expires: 180

v=0
o=Idefisk_user 6056184806875838134 13270 IN IP4 192.168.8.222
s=Idefisk_user
c=IN IP4 74.x.x.x.
t=0 0
m=audio 1306 RTP/AVP 97 101
a=fmtp:101  0-15
a=rtpmap:97 iLBC/8000
a=rtpmap:101 telephone-event/8000

SIP/2.0 100 Trying
Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Length: 0

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Length: 0

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Length: 0

SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Type: application/sdp
Content-Length: 259

v=0
o=root 7723 7723 IN IP4 64.x.x.x
s=session
c=IN IP4 74.x.x.x.
t=0 0
m=audio 1304 RTP/AVP 97 101
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

SIP/2.0 200 OK
Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Type: application/sdp
Content-Length: 259

v=0
o=root 7723 7724 IN IP4 64.x.x.x
s=session
c=IN IP4 64.x.x.x
t=0 0
m=audio 50450 RTP/AVP 97 101
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
Record-Route: <sip:1510495xxxx@74.x.x.x.;lr=on;did=935.96fcf79>
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 INVITE
User-Agent: iWorld
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:1510495xxxx@64.x.x.x>
Content-Type: application/sdp
Content-Length: 259
Session-Expires: 180;refresher=uac

v=0
o=root 7723 7724 IN IP4 64.x.x.x
s=session
c=IN IP4 74.x.x.x.
t=0 0
m=audio 1304 RTP/AVP 97 101
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:30
a=sendrecv

ACK sip:1510495xxxx@64.x.x.x SIP/2.0
Via: SIP/2.0/UDP 192.168.8.222:5068;branch=z9hG4bK-d87543-fc30fd0917758e54-1--d87543-;rport
Max-Forwards: 70
Route: <sip:1510495xxxx@74.x.x.x.;lr;did=935.96fcf79>
Contact: <sip:1111@192.168.8.222:5068>
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 ACK
Proxy-Authorization: Digest username="1111",realm="74.x.x.x.",nonce="4c754fc500000003cc350d97ea9ab177ce47146b80f9b7a5",uri="sip:1510495xxxx@74.x.x.x.",response="8037cc4b5b1bc6c822f7742c02f3e7e0",algorithm=MD5
User-Agent: Idefisk
Content-Length: 0

ACK sip:1510495xxxx@64.x.x.x SIP/2.0
Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.2
Via: SIP/2.0/UDP 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-fc30fd0917758e54-1--d87543-;rport=5068
Max-Forwards: 69
Contact: <sip:1111@173.x.x.x:5068>
To: <sip:1510495xxxx@74.x.x.x.>;tag=as3154366e
From: "1111"<sip:1111@74.x.x.x.>;tag=5145635c
Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
CSeq: 2 ACK
Proxy-Authorization: Digest username="1111",realm="74.x.x.x.",nonce="4c754fc500000003cc350d97ea9ab177ce47146b80f9b7a5",uri="sip:1510495xxxx@74.x.x.x.",response="8037cc4b5b1bc6c822f7742c02f3e7e0",algorithm=MD5
User-Agent: Idefisk
Content-Length: 01111@64.x.x.x@64.x.x.x1111@173.x.x.x




Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: start with tl=0x7fb34b920ec0 tl->prev=0x7fb34b8ec938 tl->next=0x7fb34b8ec938 (375) at 375 and end with end=0x7fb34b8ec938 end->prev=0x7fb34b920ec0 end->next=0x7fb34b920ec0
Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: getting tl=0x7fb34b920ec0 tl->prev=0x7fb34b8ec938 tl->next=0x7fb34b8ec938 with 375
Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: end with tl=0x7fb34b8ec938 tl->prev=0x7fb34b920ec0 tl->next=0x7fb34b920ec0 and d_timer->first.next->prev=(nil)
Aug 25 17:19:05 [14748] DBG:dialog:dlg_timer_routine: tl=0x7fb34b920ec0 next=(nil)
Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: sending BYE to caller (0)
Aug 25 17:19:05 [14748] DBG:dialog:ref_dlg: ref dlg 0x7fb34b920e88 with 1 -> 3
Aug 25 17:19:05 [14748] DBG:tm:t_uac: next_hop=<sip:1111@173.8.136.75:5068>
Aug 25 17:19:05 [14748] DBG:core:mk_proxy: doing DNS lookup...
Aug 25 17:19:05 [14748] DBG:tm:dlg2hash: 38254
Aug 25 17:19:05 [14748] DBG:tm:print_request_uri: sip:1111@173.8.136.75:5068
Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 500000
Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [4]: 0x7fb34b91d288 (375500000)
Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 30
Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [0]: 0x7fb34b91d2b8 (405)
Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: BYE sent to caller
Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: sending BYE to callee (1)
Aug 25 17:19:05 [14748] DBG:dialog:ref_dlg: ref dlg 0x7fb34b920e88 with 1 -> 4
Aug 25 17:19:05 [14748] DBG:tm:t_uac: next_hop=<sip:1510495@64.74.140.57>
Aug 25 17:19:05 [14748] DBG:core:mk_proxy: doing DNS lookup...
Aug 25 17:19:05 [14748] DBG:tm:dlg2hash: 38254
Aug 25 17:19:05 [14748] DBG:tm:print_request_uri: sip:1510495@64.74.140.57
Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 500000
Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [4]: 0x7fb34b921b58 (375500000)
Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 30
Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [0]: 0x7fb34b921b88 (405)
Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: BYE sent to callee
Aug 25 17:19:05 [14748] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with 1 -> 3
Aug 25 17:19:05 [14746] DBG:core:parse_msg: SIP Reply  (status):
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  version: <SIP/2.0>
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  status:  <200>
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  reason:  <OK>
Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=2
Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe659.8c40efb6.0>; state=6
Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 234, <received> = <74.x.x.x.x>; state=16
Aug 25 17:19:05 [14746] DBG:core:parse_via: end of header reached, state=5
Aug 25 17:19:05 [14746] DBG:core:parse_headers: via found, flags=2
Aug 25 17:19:05 [14746] DBG:core:parse_headers: this is the first via
Aug 25 17:19:05 [14746] DBG:core:receive_msg: After parse_msg...
Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [74.x.x.x.x] == [74.x.x.x.x]
Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Aug 25 17:19:05 [14746] DBG:core:forward_reply: found module tm, passing reply to it
Aug 25 17:19:05 [14746] DBG:tm:t_check: start=0xffffffffffffffff
Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=22
Aug 25 17:19:05 [14746] DBG:core:parse_to_param: tag=as3154366e
Aug 25 17:19:05 [14746] DBG:core:parse_to: end of header reached, state=29
Aug 25 17:19:05 [14746] DBG:core:parse_to: display={}, ruri={sip:1510495@74.x.x.x.x}
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: <To> [48]; uri=[sip:1510495@74.x.x.x.x]
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: to body [<sip:1510495@74.x.x.x.x>]
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: hash 38254 label 1811809480 branch 0
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: reply matched (T=0x7fb34b921938)!
Aug 25 17:19:05 [14746] DBG:tm:t_check: end=0x7fb34b921938
Aug 25 17:19:05 [14746] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Aug 25 17:19:05 [14746] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Aug 25 17:19:05 [14746] DBG:tm:local_reply: branch=0, save=0, winner=0
Aug 25 17:19:05 [14746] DBG:tm:local_reply: local transaction completed
Aug 25 17:19:05 [14746] DBG:tm:run_trans_callbacks: trans=0x7fb34b921938, callback type 512, id 0 entered
Aug 25 17:19:05 [14746] DBG:dialog:bye_reply_cb: receiving a final reply 200
Aug 25 17:19:05 [14746] DBG:dialog:next_state_dlg: dialog 0x7fb34b920e88 changed from state 4 to state 5, due event 7
Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: removing dialog with h_entry 1337 and h_id 159371113
Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: dlg already expired (not in timer list) 0x7fb34b920e88 [1337:159371113] with clid 'OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.' and tags '5145635c' 'as3154366e'
Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88, type=32
Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88, type=32
Aug 25 17:19:05 [14746] DBG:sst:sst_dialog_terminate_CB: Terminating DID 0x7fb34b920e88 session
Aug 25 17:19:05 [14746] DBG:sst:sst_dialog_terminate_CB: freeing the sst_info_t from dialog 0x7fb34b920e88
Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: first final reply
Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with 2 -> 1
Aug 25 17:19:05 [14746] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Aug 25 17:19:05 [14746] DBG:tm:insert_timer_unsafe: [2]: 0x7fb34b9219b8 (380)
Aug 25 17:19:05 [14746] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Aug 25 17:19:05 [14746] DBG:core:destroy_avp_list: destroying list (nil)
Aug 25 17:19:05 [14746] DBG:core:receive_msg: cleaning up
Aug 25 17:19:05 [14746] DBG:core:parse_msg: SIP Reply  (status):
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  version: <SIP/2.0>
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  status:  <200>
Aug 25 17:19:05 [14746] DBG:core:parse_msg:  reason:  <OK>
Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=2
Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe659.7c40efb6.0>; state=16
Aug 25 17:19:05 [14746] DBG:core:parse_via: end of header reached, state=5
Aug 25 17:19:05 [14746] DBG:core:parse_headers: via found, flags=2
Aug 25 17:19:05 [14746] DBG:core:parse_headers: this is the first via
Aug 25 17:19:05 [14746] DBG:core:receive_msg: After parse_msg...
Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [74.x.x.x.x] == [74.x.x.x.x]
Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Aug 25 17:19:05 [14746] DBG:core:forward_reply: found module tm, passing reply to it
Aug 25 17:19:05 [14746] DBG:tm:t_check: start=0xffffffffffffffff
Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=22
Aug 25 17:19:05 [14746] DBG:core:parse_to_param: tag=5145635c
Aug 25 17:19:05 [14746] DBG:core:parse_to: end of header reached, state=29
Aug 25 17:19:05 [14746] DBG:core:parse_to: display={}, ruri={sip:1111@74.x.x.x.x}
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: <To> [39]; uri=[sip:1111@74.x.x.x.x]
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: to body [<sip:1111@74.x.x.x.x>]
Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: hash 38254 label 1811809479 branch 0
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: reply matched (T=0x7fb34b91d068)!
Aug 25 17:19:05 [14746] DBG:tm:t_check: end=0x7fb34b91d068
Aug 25 17:19:05 [14746] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Aug 25 17:19:05 [14746] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Aug 25 17:19:05 [14746] DBG:tm:local_reply: branch=0, save=0, winner=0
Aug 25 17:19:05 [14746] DBG:tm:local_reply: local transaction completed
Aug 25 17:19:05 [14746] DBG:tm:run_trans_callbacks: trans=0x7fb34b91d068, callback type 512, id 0 entered
Aug 25 17:19:05 [14746] DBG:dialog:bye_reply_cb: receiving a final reply 200
Aug 25 17:19:05 [14746] DBG:dialog:next_state_dlg: dialog 0x7fb34b920e88 changed from state 5 to state 5, due event 7
Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: second final reply
Aug 25 17:19:05 [14746] DBG:dialog:remove_dialog_from_db: trying to remove a dialog, update_flag is 28
Aug 25 17:19:05 [14746] DBG:db_mysql:has_stmt_ctx: ctx found for dialog
Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7cc640 (tail=8166584) MC=0x7c9d18
Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_val2bind: added val (0): len=4; type=3; is_null=0
Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_val2bind: added val (1): len=4; type=3; is_null=0
Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Aug 25 17:19:05 [14746] DBG:dialog:remove_dialog_from_db: callid was OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with 1 -> 0
Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: ref <=0 for dialog 0x7fb34b920e88
Aug 25 17:19:05 [14746] DBG:dialog:destroy_dlg: destroing dialog 0x7fb34b920e88
Aug 25 17:19:05 [14746] DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x7fb34b920e88 [1337:159371113] with clid 'OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.' and tags '5145635c' 'as3154366e'
Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88, type=2048
Aug 25 17:19:05 [14746] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Aug 25 17:19:05 [14746] DBG:tm:insert_timer_unsafe: [2]: 0x7fb34b91d0e8 (380)
Aug 25 17:19:05 [14746] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Aug 25 17:19:05 [14746] DBG:core:destroy_avp_list: destroying list (nil)
Aug 25 17:19:05 [14746] DBG:core:receive_msg: cleaning up
Aug 25 17:19:05 [14748] DBG:tm:utimer_routine: timer routine:4,tl=0x7fb34b91d288 next=0x7fb34b921b58, timeout=375500000
Aug 25 17:19:05 [14748] DBG:tm:utimer_routine: timer routine:4,tl=0x7fb34b921b58 next=(nil), timeout=375500000
Aug 25 17:19:10 [14748] DBG:tm:timer_routine: timer routine:2,tl=0x7fb34b9219b8 next=0x7fb34b91d0e8, timeout=380
Aug 25 17:19:10 [14748] DBG:tm:wait_handler: removing 0x7fb34b921938 from table
Aug 25 17:19:10 [14748] DBG:tm:delete_cell: delete transaction 0x7fb34b921938
Aug 25 17:19:10 [14748] DBG:tm:wait_handler: done
Aug 25 17:19:10 [14748] DBG:tm:timer_routine: timer routine:2,tl=0x7fb34b91d0e8 next=(nil), timeout=380
Aug 25 17:19:10 [14748] DBG:tm:wait_handler: removing 0x7fb34b91d068 from table
Aug 25 17:19:10 [14748] DBG:tm:delete_cell: delete transaction 0x7fb34b91d068
Aug 25 17:19:10 [14748] DBG:tm:wait_handler: done

Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

Bogdan-Andrei Iancu
Hi,

I see that the signalling requires a re-INVITE after 180 secs (3
minutes) - the SST + DIALOG module will terminate the dialog if there is
no such re-INVITE.

Unfortunatelly the trace has no timestamps to see if the dialog module
fires the BYE after 3 minutes.

The re-INVITE must be fires by UAC (see in 200 OK : Session-Expires:
180;refresher=uac )

Regards,
Bogdan

k1028 wrote:

> The call is established but terminated after some time.
>
> Here is the SIP trace from siptrace module and debug 5 from Opensips. There
> is no BYE in the SIPTrace. Debug 5 from Opensips did show BYE sent to caller
> and to callee from dialog module.
>
> INVITE sip:[hidden email]. SIP/2.0
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Max-Forwards: 69
> Contact: <sip:[hidden email]:5068>
> To: <sip:[hidden email].>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, NOTIFY, REFER, MESSAGE, OPTIONS
> Content-Type: application/sdp
> User-Agent: Idefisk
> Content-Length: 220
> Session-Expires: 180
>
> v=0
> o=Idefisk_user 6056184806875838134 13270 IN IP4 192.168.8.222
> s=Idefisk_user
> c=IN IP4 74.x.x.x.
> t=0 0
> m=audio 1306 RTP/AVP 97 101
> a=fmtp:101  0-15
> a=rtpmap:97 iLBC/8000
> a=rtpmap:101 telephone-event/8000
>
> SIP/2.0 100 Trying
> Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Length: 0
>
> SIP/2.0 180 Ringing
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>;tag=as3154366e
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Length: 0
>
> SIP/2.0 180 Ringing
> Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>;tag=as3154366e
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Length: 0
>
> SIP/2.0 183 Session Progress
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>;tag=as3154366e
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Type: application/sdp
> Content-Length: 259
>
> v=0
> o=root 7723 7723 IN IP4 64.x.x.x
> s=session
> c=IN IP4 74.x.x.x.
> t=0 0
> m=audio 1304 RTP/AVP 97 101
> a=rtpmap:97 iLBC/8000
> a=fmtp:97 mode=30
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:30
> a=sendrecv
>
> SIP/2.0 200 OK
> Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.0;received=74.x.x.x.
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>;tag=as3154366e
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Type: application/sdp
> Content-Length: 259
>
> v=0
> o=root 7723 7724 IN IP4 64.x.x.x
> s=session
> c=IN IP4 64.x.x.x
> t=0 0
> m=audio 50450 RTP/AVP 97 101
> a=rtpmap:97 iLBC/8000
> a=fmtp:97 mode=30
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:30
> a=sendrecv
>
> SIP/2.0 200 OK
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-21170d43ec319d0c-1--d87543-;rport=5068
> Record-Route: <sip:[hidden email].;lr=on;did=935.96fcf79>
> From: "1111"<sip:[hidden email].>;tag=5145635c
> To: <sip:[hidden email].>;tag=as3154366e
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 INVITE
> User-Agent: iWorld
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
> Supported: replaces
> Contact: <sip:[hidden email]>
> Content-Type: application/sdp
> Content-Length: 259
> Session-Expires: 180;refresher=uac
>
> v=0
> o=root 7723 7724 IN IP4 64.x.x.x
> s=session
> c=IN IP4 74.x.x.x.
> t=0 0
> m=audio 1304 RTP/AVP 97 101
> a=rtpmap:97 iLBC/8000
> a=fmtp:97 mode=30
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:30
> a=sendrecv
>
> ACK sip:[hidden email] SIP/2.0
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;branch=z9hG4bK-d87543-fc30fd0917758e54-1--d87543-;rport
> Max-Forwards: 70
> Route: <sip:[hidden email].;lr;did=935.96fcf79>
> Contact: <sip:1111@192.168.8.222:5068>
> To: <sip:[hidden email].>;tag=as3154366e
> From: "1111"<sip:[hidden email].>;tag=5145635c
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 ACK
> Proxy-Authorization: Digest
> username="1111",realm="74.x.x.x.",nonce="4c754fc500000003cc350d97ea9ab177ce47146b80f9b7a5",uri="sip:[hidden email].",response="8037cc4b5b1bc6c822f7742c02f3e7e0",algorithm=MD5
> User-Agent: Idefisk
> Content-Length: 0
>
> ACK sip:[hidden email] SIP/2.0
> Via: SIP/2.0/UDP 74.x.x.x.;branch=z9hG4bKd659.0ab95ac3.2
> Via: SIP/2.0/UDP
> 192.168.8.222:5068;received=173.x.x.x;branch=z9hG4bK-d87543-fc30fd0917758e54-1--d87543-;rport=5068
> Max-Forwards: 69
> Contact: <sip:[hidden email]:5068>
> To: <sip:[hidden email].>;tag=as3154366e
> From: "1111"<sip:[hidden email].>;tag=5145635c
> Call-ID: OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> CSeq: 2 ACK
> Proxy-Authorization: Digest
> username="1111",realm="74.x.x.x.",nonce="4c754fc500000003cc350d97ea9ab177ce47146b80f9b7a5",uri="sip:[hidden email].",response="8037cc4b5b1bc6c822f7742c02f3e7e0",algorithm=MD5
> User-Agent: Idefisk
> Content-Length: [hidden email]@[hidden email]
>
>
>
>
> Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: start with
> tl=0x7fb34b920ec0 tl->prev=0x7fb34b8ec938 tl->next=0x7fb34b8ec938 (375) at
> 375 and end with end=0x7fb34b8ec938 end->prev=0x7fb34b920ec0
> end->next=0x7fb34b920ec0
> Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: getting
> tl=0x7fb34b920ec0 tl->prev=0x7fb34b8ec938 tl->next=0x7fb34b8ec938 with 375
> Aug 25 17:19:05 [14748] DBG:dialog:get_expired_dlgs: end with
> tl=0x7fb34b8ec938 tl->prev=0x7fb34b920ec0 tl->next=0x7fb34b920ec0 and
> d_timer->first.next->prev=(nil)
> Aug 25 17:19:05 [14748] DBG:dialog:dlg_timer_routine: tl=0x7fb34b920ec0
> next=(nil)
> Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: sending BYE to caller (0)
> Aug 25 17:19:05 [14748] DBG:dialog:ref_dlg: ref dlg 0x7fb34b920e88 with 1 ->
> 3
> Aug 25 17:19:05 [14748] DBG:tm:t_uac: next_hop=<sip:1111@173.8.136.75:5068>
> Aug 25 17:19:05 [14748] DBG:core:mk_proxy: doing DNS lookup...
> Aug 25 17:19:05 [14748] DBG:tm:dlg2hash: 38254
> Aug 25 17:19:05 [14748] DBG:tm:print_request_uri: sip:1111@173.8.136.75:5068
> Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 500000
> Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [4]: 0x7fb34b91d288
> (375500000)
> Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 30
> Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [0]: 0x7fb34b91d2b8
> (405)
> Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: BYE sent to caller
> Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: sending BYE to callee (1)
> Aug 25 17:19:05 [14748] DBG:dialog:ref_dlg: ref dlg 0x7fb34b920e88 with 1 ->
> 4
> Aug 25 17:19:05 [14748] DBG:tm:t_uac: next_hop=<sip:1510495@64.74.140.57>
> Aug 25 17:19:05 [14748] DBG:core:mk_proxy: doing DNS lookup...
> Aug 25 17:19:05 [14748] DBG:tm:dlg2hash: 38254
> Aug 25 17:19:05 [14748] DBG:tm:print_request_uri: sip:1510495@64.74.140.57
> Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 500000
> Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [4]: 0x7fb34b921b58
> (375500000)
> Aug 25 17:19:05 [14748] DBG:tm:set_timer: relative timeout is 30
> Aug 25 17:19:05 [14748] DBG:tm:insert_timer_unsafe: [0]: 0x7fb34b921b88
> (405)
> Aug 25 17:19:05 [14748] DBG:dialog:send_leg_bye: BYE sent to callee
> Aug 25 17:19:05 [14748] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with
> 1 -> 3
> Aug 25 17:19:05 [14746] DBG:core:parse_msg: SIP Reply  (status):
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  version: <SIP/2.0>
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  status:  <200>
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  reason:  <OK>
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=2
> Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 232,
> <branch> = <z9hG4bKe659.8c40efb6.0>; state=6
> Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 234,
> <received> = <74.x.x.x.x>; state=16
> Aug 25 17:19:05 [14746] DBG:core:parse_via: end of header reached, state=5
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: via found, flags=2
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: this is the first via
> Aug 25 17:19:05 [14746] DBG:core:receive_msg: After parse_msg...
> Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if host==us:
> 13==13 &&  [74.x.x.x.x] == [74.x.x.x.x]
> Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if port 5060
> matches port 5060
> Aug 25 17:19:05 [14746] DBG:core:forward_reply: found module tm, passing
> reply to it
> Aug 25 17:19:05 [14746] DBG:tm:t_check: start=0xffffffffffffffff
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=22
> Aug 25 17:19:05 [14746] DBG:core:parse_to_param: tag=as3154366e
> Aug 25 17:19:05 [14746] DBG:core:parse_to: end of header reached, state=29
> Aug 25 17:19:05 [14746] DBG:core:parse_to: display={},
> ruri={sip:[hidden email]}
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: <To> [48];
> uri=[sip:[hidden email]]
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: to body
> [<sip:[hidden email]>]
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: hash 38254 label 1811809480
> branch 0
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: reply matched
> (T=0x7fb34b921938)!
> Aug 25 17:19:05 [14746] DBG:tm:t_check: end=0x7fb34b921938
> Aug 25 17:19:05 [14746] DBG:tm:reply_received: org. status uas=0, uac[0]=0
> local=2 is_invite=0)
> Aug 25 17:19:05 [14746] DBG:tm:t_should_relay_response: T_code=0,
> new_code=200
> Aug 25 17:19:05 [14746] DBG:tm:local_reply: branch=0, save=0, winner=0
> Aug 25 17:19:05 [14746] DBG:tm:local_reply: local transaction completed
> Aug 25 17:19:05 [14746] DBG:tm:run_trans_callbacks: trans=0x7fb34b921938,
> callback type 512, id 0 entered
> Aug 25 17:19:05 [14746] DBG:dialog:bye_reply_cb: receiving a final reply 200
> Aug 25 17:19:05 [14746] DBG:dialog:next_state_dlg: dialog 0x7fb34b920e88
> changed from state 4 to state 5, due event 7
> Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: removing dialog with
> h_entry 1337 and h_id 159371113
> Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: dlg already expired (not
> in timer list) 0x7fb34b920e88 [1337:159371113] with clid
> 'OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.' and tags '5145635c'
> 'as3154366e'
> Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88,
> type=32
> Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88,
> type=32
> Aug 25 17:19:05 [14746] DBG:sst:sst_dialog_terminate_CB: Terminating DID
> 0x7fb34b920e88 session
> Aug 25 17:19:05 [14746] DBG:sst:sst_dialog_terminate_CB: freeing the
> sst_info_t from dialog 0x7fb34b920e88
> Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: first final reply
> Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with
> 2 -> 1
> Aug 25 17:19:05 [14746] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
> Aug 25 17:19:05 [14746] DBG:tm:insert_timer_unsafe: [2]: 0x7fb34b9219b8
> (380)
> Aug 25 17:19:05 [14746] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
> Aug 25 17:19:05 [14746] DBG:core:destroy_avp_list: destroying list (nil)
> Aug 25 17:19:05 [14746] DBG:core:receive_msg: cleaning up
> Aug 25 17:19:05 [14746] DBG:core:parse_msg: SIP Reply  (status):
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  version: <SIP/2.0>
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  status:  <200>
> Aug 25 17:19:05 [14746] DBG:core:parse_msg:  reason:  <OK>
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=2
> Aug 25 17:19:05 [14746] DBG:core:parse_via_param: found param type 232,
> <branch> = <z9hG4bKe659.7c40efb6.0>; state=16
> Aug 25 17:19:05 [14746] DBG:core:parse_via: end of header reached, state=5
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: via found, flags=2
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: this is the first via
> Aug 25 17:19:05 [14746] DBG:core:receive_msg: After parse_msg...
> Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if host==us:
> 13==13 &&  [74.x.x.x.x] == [74.x.x.x.x]
> Aug 25 17:19:05 [14746] DBG:core:grep_sock_info: checking if port 5060
> matches port 5060
> Aug 25 17:19:05 [14746] DBG:core:forward_reply: found module tm, passing
> reply to it
> Aug 25 17:19:05 [14746] DBG:tm:t_check: start=0xffffffffffffffff
> Aug 25 17:19:05 [14746] DBG:core:parse_headers: flags=22
> Aug 25 17:19:05 [14746] DBG:core:parse_to_param: tag=5145635c
> Aug 25 17:19:05 [14746] DBG:core:parse_to: end of header reached, state=29
> Aug 25 17:19:05 [14746] DBG:core:parse_to: display={},
> ruri={sip:[hidden email]}
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: <To> [39];
> uri=[sip:[hidden email]]
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: to body
> [<sip:[hidden email]>]
> Aug 25 17:19:05 [14746] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: hash 38254 label 1811809479
> branch 0
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
> Aug 25 17:19:05 [14746] DBG:tm:t_reply_matching: reply matched
> (T=0x7fb34b91d068)!
> Aug 25 17:19:05 [14746] DBG:tm:t_check: end=0x7fb34b91d068
> Aug 25 17:19:05 [14746] DBG:tm:reply_received: org. status uas=0, uac[0]=0
> local=2 is_invite=0)
> Aug 25 17:19:05 [14746] DBG:tm:t_should_relay_response: T_code=0,
> new_code=200
> Aug 25 17:19:05 [14746] DBG:tm:local_reply: branch=0, save=0, winner=0
> Aug 25 17:19:05 [14746] DBG:tm:local_reply: local transaction completed
> Aug 25 17:19:05 [14746] DBG:tm:run_trans_callbacks: trans=0x7fb34b91d068,
> callback type 512, id 0 entered
> Aug 25 17:19:05 [14746] DBG:dialog:bye_reply_cb: receiving a final reply 200
> Aug 25 17:19:05 [14746] DBG:dialog:next_state_dlg: dialog 0x7fb34b920e88
> changed from state 5 to state 5, due event 7
> Aug 25 17:19:05 [14746] DBG:dialog:dual_bye_event: second final reply
> Aug 25 17:19:05 [14746] DBG:dialog:remove_dialog_from_db: trying to remove a
> dialog, update_flag is 28
> Aug 25 17:19:05 [14746] DBG:db_mysql:has_stmt_ctx: ctx found for dialog
> Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query:
> conn=0x7cc640 (tail=8166584) MC=0x7c9d18
> Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query: set values
> for the statement run
> Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_val2bind: added val (0):
> len=4; type=3; is_null=0
> Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_val2bind: added val (1):
> len=4; type=3; is_null=0
> Aug 25 17:19:05 [14746] DBG:db_mysql:db_mysql_do_prepared_query: doing
> BIND_PARAM in...
> Aug 25 17:19:05 [14746] DBG:dialog:remove_dialog_from_db: callid was
> OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.
> Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: unref dlg 0x7fb34b920e88 with
> 1 -> 0
> Aug 25 17:19:05 [14746] DBG:dialog:unref_dlg: ref <=0 for dialog
> 0x7fb34b920e88
> Aug 25 17:19:05 [14746] DBG:dialog:destroy_dlg: destroing dialog
> 0x7fb34b920e88
> Aug 25 17:19:05 [14746] DBG:dialog:destroy_dlg: dlg expired or not in list -
> dlg 0x7fb34b920e88 [1337:159371113] with clid
> 'OThhNWNjOWNjZWFmZDkwMmFlNTExYmVmNTM1ZTE2NjM.' and tags '5145635c'
> 'as3154366e'
> Aug 25 17:19:05 [14746] DBG:dialog:run_dlg_callbacks: dialog=0x7fb34b920e88,
> type=2048
> Aug 25 17:19:05 [14746] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
> Aug 25 17:19:05 [14746] DBG:tm:insert_timer_unsafe: [2]: 0x7fb34b91d0e8
> (380)
> Aug 25 17:19:05 [14746] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
> Aug 25 17:19:05 [14746] DBG:core:destroy_avp_list: destroying list (nil)
> Aug 25 17:19:05 [14746] DBG:core:receive_msg: cleaning up
> Aug 25 17:19:05 [14748] DBG:tm:utimer_routine: timer
> routine:4,tl=0x7fb34b91d288 next=0x7fb34b921b58, timeout=375500000
> Aug 25 17:19:05 [14748] DBG:tm:utimer_routine: timer
> routine:4,tl=0x7fb34b921b58 next=(nil), timeout=375500000
> Aug 25 17:19:10 [14748] DBG:tm:timer_routine: timer
> routine:2,tl=0x7fb34b9219b8 next=0x7fb34b91d0e8, timeout=380
> Aug 25 17:19:10 [14748] DBG:tm:wait_handler: removing 0x7fb34b921938 from
> table
> Aug 25 17:19:10 [14748] DBG:tm:delete_cell: delete transaction
> 0x7fb34b921938
> Aug 25 17:19:10 [14748] DBG:tm:wait_handler: done
> Aug 25 17:19:10 [14748] DBG:tm:timer_routine: timer
> routine:2,tl=0x7fb34b91d0e8 next=(nil), timeout=380
> Aug 25 17:19:10 [14748] DBG:tm:wait_handler: removing 0x7fb34b91d068 from
> table
> Aug 25 17:19:10 [14748] DBG:tm:delete_cell: delete transaction
> 0x7fb34b91d068
> Aug 25 17:19:10 [14748] DBG:tm:wait_handler: done
>
>
>  


--
Bogdan-Andrei Iancu
OpenSIPS Bootcamp
20 - 24 September 2010, Frankfurt, Germany
www.voice-system.ro


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

k1028
Thank you very much for your response. I will look into the re-invite problem now.

There is no BYE in the SIPTrace from the SIPTrace module associated to this. The first Invite is received at 17:15:19 and the last ACK is at 17:16:05 from SIPTrace module. The dialog module send BYE at 17:19:05
Reply | Threaded
Open this post in threaded view
|

Re: Opensips 1.6.2 to 1.6.3 SST module question

Bogdan-Andrei Iancu
Hi,

the BYEs are generated by opensips (internally), so the SIPtrace module
will not get them - but if you use ngrep/tcpdump, you will see them.

So, you have 3 minutes between 200OK / ACK and BYE....exactly the
Session-Expires :)

Best regards,
Bogdan

k1028 wrote:
> Thank you very much for your response. I will look into the re-invite problem
> now.
>
> There is no BYE in the SIPTrace from the SIPTrace module associated to this.
> The first Invite is received at 17:15:19 and the last ACK is at 17:16:05
> from SIPTrace module. The dialog module send BYE at 17:19:05
>  


--
Bogdan-Andrei Iancu
OpenSIPS Bootcamp
20 - 24 September 2010, Frankfurt, Germany
www.voice-system.ro


_______________________________________________
Users mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users