in another ivr app, sems receives invite from [email protected] and sends out invite using connectCallee call to [email protected]. after that sems sends re-invites to both parties.
wireshark shows all messages flowing without problems, but then while the call has been connected between jh and test for five seconds, sems sends bye to test and i cannot figure out why. this app used to work fine earlier, although i don't remember in which version of sems. below is debug log from the point when sems has received 200 ok from test to re-invite and sends out ack. then 5 seconds later sems sends bye to test. does the log give any clue why sems sends the bye? -- juha May 20 20:42:32 sip sems[10789]: [#b60d1b70] [run, udp_trsp.cpp:213] DEBUG: vv M [|] u recvd msg via UDP vv#012--++--#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;rport=5090;branch=z9hG4bKD7vAmaqn#015#012To: <sip:[email protected]>;tag=mqtxy#015#012From: "Juha Heinanen" <sip:[email protected]>;tag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70#015#012Call-ID: 7B24EECE-4DD6A8070006E81C-B5A6AB70#015#012CSeq: 11 INVITE#015#012Contact: <sip:[email protected];alias=192.168.1.2~59405~1>#015#012Content-Type: application/sdp#015#012Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE#015#012Server: Twinkle/1.4.2#015#012Supported: replaces,norefersub#015#012Content-Length: 199#015#012#015#012v=0#015#012o=twinkle 1396001893 100602166 IN IP4 192.168.0.43#015#012s=-#015#012c=IN IP4 192.98.102.10#015#012t=0 0#015#012m=audio 50032 RTP/AVP 97 101#015#012a=rtpmap:97 speex/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012--++-- May 20 20:42:32 sip sems[10789]: [#b60d1b70] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKD7vAmaqn May 20 20:42:32 sip sems[10789]: [#b60d1b70] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 May 20 20:42:32 sip sems[10789]: [#b60d1b70] [received_msg, trans_layer.cpp:1204] DEBUG: Reply matched an existing transaction May 20 20:42:32 sip sems[10789]: [#b60d1b70] [update_uac_reply, trans_layer.cpp:1247] DEBUG: update_uac_reply(reply code = 200, trans=0x99357b0) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [update_uac_reply, trans_layer.cpp:1316] DEBUG: Positive final reply to INVITE transaction (state=2) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [reset_timer, sip_trans.cpp:139] DEBUG: Clearing old timer of type A (this=0x99482e8) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [reset_timer, sip_trans.cpp:139] DEBUG: Clearing old timer of type M (this=0x9955d60) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [reset_timer, sip_trans.cpp:139] DEBUG: Clearing old timer of type B (this=0x994f590) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [reset_timer, sip_trans.cpp:185] DEBUG: New timer of type L at time=123593 (repeated=0) May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:626] DEBUG: Received reply: 200 OK May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:627] DEBUG: reply.callid = <7B24EECE-4DD6A8070006E81C-B5A6AB70> May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:628] DEBUG: reply.local_tag = <3ADC7AE1-4DD6A8070006E7F7-B5A6AB70> May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:629] DEBUG: reply.remote_tag = <mqtxy> May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:630] DEBUG: cseq = <11> May 20 20:42:32 sip sems[10789]: [#b60d1b70] [handle_sip_reply, SipCtrlInterface.cpp:636] DEBUG: ^^ M [7B24EECE-4DD6A8070006E81C-B5A6AB70|3ADC7AE1-4DD6A8070006E7F7-B5A6AB70] ru SIP reply 200 OK handled ^^ May 20 20:42:32 sip sems[10789]: [#b57ffb70] [processingCycle, AmSession.cpp:445] DEBUG: vv S [7B24EECE-4DD6A8070006E81C-B5A6AB70|3ADC7AE1-4DD6A8070006E7F7-B5A6AB70] Connected, running, 1 UACTransPending vv May 20 20:42:32 sip sems[10789]: [#b57ffb70] [process, AmSession.cpp:785] DEBUG: AmSession processing event May 20 20:42:32 sip sems[10789]: [#b57ffb70] [updateStatus, AmSipDialog.cpp:317] DEBUG: updateStatus(rep = 200 OK): transaction found! May 20 20:42:32 sip sems[10789]: [#b57ffb70] [onInvite2xx, AmB2BSession.cpp:451] DEBUG: req not fwded May 20 20:42:32 sip sems[10789]: [#b57ffb70] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port (5080) to int (5080) May 20 20:42:32 sip sems[10789]: [#b57ffb70] [set_destination_ip, trans_layer.cpp:683] DEBUG: checking whether '127.0.0.1' is IP address... May 20 20:42:32 sip sems[10789]: [#b57ffb70] [set_destination_ip, trans_layer.cpp:725] DEBUG: set destination to 127.0.0.1:5080 May 20 20:42:32 sip sems[10789]: [#b57ffb70] [send_request, trans_layer.cpp:820] DEBUG: send_request to R-URI <sip:[email protected];alias=192.168.1.2~59405~1> May 20 20:42:32 sip sems[10789]: [#b57ffb70] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port () to int (5060) May 20 20:42:32 sip sems[10789]: [#b57ffb70] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKb9ohsaQG May 20 20:42:32 sip sems[10789]: [#b57ffb70] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 May 20 20:42:32 sip sems[10789]: [#b57ffb70] [send_request, trans_layer.cpp:889] DEBUG: Sending to 127.0.0.1:5080 <ACK sip:[email protected];alias=192.168.1.2~59405~...> May 20 20:42:32 sip sems[10789]: [#b57ffb70] [send, transport.cpp:98] DEBUG: send msg#012--++--#012ACK sip:[email protected];alias=192.168.1.2~59405~1 SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKb9ohsaQG;rport#015#012From: "Juha Heinanen" <sip:[email protected]>;tag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70#015#012To: sip:[email protected];tag=mqtxy#015#012CSeq: 11 ACK#015#012Call-ID: 7B24EECE-4DD6A8070006E81C-B5A6AB70#015#012Contact: <sip:127.0.0.1:5090>#015#012Route: <sip:127.0.0.1:5080;r2=on;lr;ftag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70;n1;pm>, <sip:192.98.102.10;r2=on;lr;ftag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70;n1;pm>#015#012User-Agent: Sip Express Media Server (rexported (x86/linux))#015#012Max-Forwards: 70#015#012Content-Length: 0#015#012#015#012--++-- May 20 20:42:32 sip sems[10789]: [#b57ffb70] [send_request, trans_layer.cpp:901] DEBUG: update_uac_request tt->_t =(nil) May 20 20:42:32 sip sems[10789]: [#b57ffb70] [match_request, trans_table.cpp:68] DEBUG: Matching ACK request May 20 20:42:32 sip sems[10789]: [#b57ffb70] [match_request, trans_table.cpp:87] DEBUG: do_3261_match = 1 May 20 20:42:32 sip sems[10789]: [#b57ffb70] [update_uac_request, trans_layer.cpp:1426] DEBUG: update_uac_request(200 ACK, t=0x99357b0) May 20 20:42:32 sip /usr/sbin/sip-proxy[3238]: INFO: Routing in-dialog ACK <sip:[email protected]> from <sip:[email protected]> to <sip:192.168.1.2:59405> May 20 20:42:32 sip sems[10789]: [#b57ffb70] [onSipReply, AmB2BSession.cpp:410] DEBUG: onSipReply: INVITE -> 200 OK (fwd=false), c-t=application/sdp May 20 20:42:32 sip sems[10789]: [#b57ffb70] [onSipReply, AmSession.cpp:907] DEBUG: Dialog status stays Connected (stopped=false) May 20 20:42:32 sip sems[10789]: [#b57ffb70] [relayEvent, AmB2BSession.cpp:461] DEBUG: AmB2BSession::relayEvent: to other_id='785D918C-4DD6A802000463E5-B5DCEB70' May 20 20:42:32 sip sems[10789]: [#b57ffb70] [processingCycle, AmSession.cpp:463] DEBUG: ^^ S [7B24EECE-4DD6A8070006E81C-B5A6AB70|3ADC7AE1-4DD6A8070006E7F7-B5A6AB70] Connected, running, 0 UACTransPending ^^ May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [processingCycle, AmSession.cpp:445] DEBUG: vv S [[email protected]|785D918C-4DD6A802000463E5-B5DCEB70] Connected, running, 0 UACTransPending vv May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [process, Ivr.cpp:767] DEBUG: IvrDialog::process May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [onB2BEvent, AmB2BSession.cpp:876] DEBUG: 200 reply received from other leg May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [onB2BEvent, AmB2BSession.cpp:147] DEBUG: B2BSipReply: 200 OK (fwd=false) May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [onB2BEvent, AmB2BSession.cpp:148] DEBUG: B2BSipReply: content-type = application/sdp May 20 20:42:32 sip sems[10789]: [#b5a6ab70] [processingCycle, AmSession.cpp:463] DEBUG: ^^ S [[email protected]|785D918C-4DD6A802000463E5-B5DCEB70] Connected, running, 0 UACTransPending ^^ May 20 20:42:37 sip sems[10789]: [#b6b34b70] [checkTimers, UserTimer.cpp:112] DEBUG: Timeout Event '1' posted to 785D918C-4DD6A802000463E5-B5DCEB70. May 20 20:42:37 sip sems[10789]: [#b5a6ab70] [processingCycle, AmSession.cpp:445] DEBUG: vv S [[email protected]|785D918C-4DD6A802000463E5-B5DCEB70] Connected, running, 0 UACTransPending vv May 20 20:42:37 sip sems[10789]: [#b5a6ab70] [process, Ivr.cpp:767] DEBUG: IvrDialog::process May 20 20:42:37 sip sems[10789]: [#b5a6ab70] [relayEvent, AmB2BSession.cpp:461] DEBUG: AmB2BSession::relayEvent: to other_id='3ADC7AE1-4DD6A8070006E7F7-B5A6AB70' May 20 20:42:37 sip sems[10789]: [#b5a6ab70] [setTimer, AmSession.cpp:1292] DEBUG: setting timer 5 with timeout 2 May 20 20:42:37 sip sems[10789]: [#b5a6ab70] [processingCycle, AmSession.cpp:463] DEBUG: ^^ S [[email protected]|785D918C-4DD6A802000463E5-B5DCEB70] Connected, running, 0 UACTransPending ^^ May 20 20:42:37 sip sems[10789]: [#b57ffb70] [processingCycle, AmSession.cpp:445] DEBUG: vv S [7B24EECE-4DD6A8070006E81C-B5A6AB70|3ADC7AE1-4DD6A8070006E7F7-B5A6AB70] Connected, running, 0 UACTransPending vv May 20 20:42:37 sip sems[10789]: [#b57ffb70] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port (5080) to int (5080) May 20 20:42:37 sip sems[10789]: [#b57ffb70] [set_destination_ip, trans_layer.cpp:683] DEBUG: checking whether '127.0.0.1' is IP address... May 20 20:42:37 sip sems[10789]: [#b57ffb70] [set_destination_ip, trans_layer.cpp:725] DEBUG: set destination to 127.0.0.1:5080 May 20 20:42:37 sip sems[10789]: [#b57ffb70] [send_request, trans_layer.cpp:820] DEBUG: send_request to R-URI <sip:[email protected];alias=192.168.1.2~59405~1> May 20 20:42:37 sip sems[10789]: [#b57ffb70] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port () to int (5060) May 20 20:42:37 sip sems[10789]: [#b57ffb70] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKzN67na~w May 20 20:42:37 sip sems[10789]: [#b57ffb70] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 May 20 20:42:37 sip sems[10789]: [#b57ffb70] [send_request, trans_layer.cpp:889] DEBUG: Sending to 127.0.0.1:5080 <BYE sip:[email protected];alias=192.168.1.2~59405~...> May 20 20:42:37 sip sems[10789]: [#b57ffb70] [send, transport.cpp:98] DEBUG: send msg#012--++--#012BYE sip:[email protected];alias=192.168.1.2~59405~1 SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKzN67na~w;rport#015#012From: "Juha Heinanen" <sip:[email protected]>;tag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70#015#012To: sip:[email protected];tag=mqtxy#015#012CSeq: 12 BYE#015#012Call-ID: 7B24EECE-4DD6A8070006E81C-B5A6AB70#015#012Route: <sip:127.0.0.1:5080;r2=on;lr;ftag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70;n1;pm>, <sip:192.98.102.10;r2=on;lr;ftag=3ADC7AE1-4DD6A8070006E7F7-B5A6AB70;n1;pm>#015#012Content-Length: 0#015#012#015#012--++-- _______________________________________________ Sems mailing list [email protected] http://lists.iptel.org/mailman/listinfo/sems
