[Nov 3 07:47:09] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (1783 bytes) from UDP:213.102.45.36:5060 ---> INVITE sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:649 From:"+37060960355" ;tag=Db0c.A_DY7C9_a25 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Call-ID:0475F5859E4B8813EF379597@1070ffffffff CSeq:1 INVITE Max-Forwards:70 Route: Record-Route: Request-Disposition:no-fork P-Asserted-Identity:, Session-Expires:1800;refresher=uac Contact: Supported:100rel,timer,norefersub Allow:ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,PRACK,REFER,UPDATE P-Charging-Vector:icid-value=c2BImQPw~~~~~~~~~~~~~wR9+oUE;icid-generated-at=213.102.45.36;orig-ioi=LTMSS2-SIP.TELE2.NET P-Early-Media:supported Content-Type:application/sdp Content-Disposition:session;handling=required v=0 o=- 0 0 IN IP4 10.20.198.213 s=- c=IN IP4 213.102.45.245 t=0 0 m=audio 60550 RTP/AVP 96 97 98 3 99 100 8 101 b=AS:80 a=rtpmap:96 AMR/8000 a=fmtp:96 mode-set=0,2,4,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:97 AMR/8000 a=fmtp:97 mode-set=0,2,5,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:98 GSM-EFR/8000 a=rtpmap:3 GSM/8000 a=rtpmap:99 AMR/8000 a=fmtp:99 mode-set=0,2,4; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:100 AMR/8000 a=fmtp:100 mode-change-capability=2; max-red=0 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=maxptime:20 [Nov 3 07:47:09] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:09] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:09] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:09] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:09] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:09] DEBUG[78495]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000038 to use for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f9834006758) [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port ''. [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 213.102.45.36:5060 does not match identify 't2-ossnet-1' [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 213.102.45.36:5060 matches identify 't2-ossnet-2' [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint t2-ossnet-2 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7f9834006758) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .Incoming Request msg INVITE/cseq=1 (rdata0x7f9834006758) in state Null [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ...Transaction tsx0x7f98b40074b8 state changed to Trying [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .UAS dialog created [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Module mod-invite added as dialog usage, data=0x7f98b4005268 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ..Session count inc to 2 by mod-invite [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Module mod-100rel added as dialog usage, data=0x7f98b400a078 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .100rel module attached [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : inv0x7f98b4006 .UAS invite session created for dialog dlg0x7f98b4006ca8 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Module Session Module added as dialog usage, data=(nil) [Nov 3 07:47:09] DEBUG[78496]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000038 to use for Request msg INVITE/cseq=1 (rdata0x7f9834006758) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ..Session count inc to 2 by Session Module [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:265 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.245' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.245' and port ''. [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:435 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f98b4011188' [Nov 3 07:47:09] DEBUG[78496]: res_rtp_asterisk.c:2621 ast_rtp_new: Allocated port 12270 for RTP instance '0x7f98b4011188' [Nov 3 07:47:09] DEBUG[78496]: res_rtp_asterisk.c:2648 ast_rtp_new: Creating ICE session 0.0.0.0:12270 (12270) for RTP instance '0x7f98b4011188' [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : icess0x7f98b40 ICE session created, comp_cnt=2, role is Unknown agent [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha280664, addr=10.40.6.100:12270, base=10.40.6.100:12270, prio=0x7effffff (2130706431) [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:444 ast_rtp_instance_new: RTP instance '0x7f98b4011188' is setup and ready to go [Nov 3 07:47:09] DEBUG[78496]: res_rtp_asterisk.c:4861 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f98b4011188' [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 1 added: comp_id=2, type=host, foundation=Ha280664, addr=10.40.6.100:12271, base=10.40.6.100:12271, prio=0x7efffffe (2130706430) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Destroying ICE session 0x7f98b4014708 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4018528 destroy request, ref_cnt=4 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4019528 destroy request, ref_cnt=3 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : ice_session.c ICE session 0x7f98b4014708 destroyed [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4018528 destroyed [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4019528 destroyed [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 98 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f98b400a150) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f98b4008ed0) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x7f98b4006bd0) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 98 (0x2b63a70) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 99 (0x7f98b4011a80) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f98b4008e70) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f98b401a7d0) from 0x7f98c14c44f0 to 0x7f98b4011350 [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:275 handle_incoming_sdp: Media stream 'audio' handled by audio [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_t38.c:736 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7f98b40057c0) created [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : inv0x7f98b4006 .Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40057c0) in state Trying [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:09] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (533 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Record-Route: Call-ID: 0475F5859E4B8813EF379597@1070ffffffff From: "+37060960355" ;tag=Db0c.A_DY7C9_a25 To: CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ...State changed from Trying to Proceeding, event=TX_MSG [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ....Transaction tsx0x7f98b40074b8 state changed to Proceeding [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:09] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is INVITE [Nov 3 07:47:09] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 Module NAT added as dialog usage, data=(nil) [Nov 3 07:47:09] DEBUG[78471]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Nov 3 07:47:09] DEBUG[78496]: chan_pjsip.c:2302 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/t2-ossnet-2-00000000 [Nov 3 07:47:09] DEBUG[78622][C-00000000]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:1] Wait("PJSIP/t2-ossnet-2-00000000", "1") in new stack [Nov 3 07:47:10] DEBUG[78622][C-00000000]: pbx.c:2825 pbx_extension_helper: Launching 'Ringing' -- Executing [963667366321@t2-ringing-test:2] Ringing("PJSIP/t2-ossnet-2-00000000", "") in new stack [Nov 3 07:47:10] DEBUG[78622][C-00000000]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' [Nov 3 07:47:10] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 -- Executing [963667366321@t2-ringing-test:3] Wait("PJSIP/t2-ossnet-2-00000000", "45") in new stack [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:10] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:47:10] DEBUG[78546]: app_queue.c:2477 device_state_cb: Device 'PJSIP/t2-ossnet-2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : inv0x7f98b4006 .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Reliable response Response msg 180/INVITE/cseq=1 (tdta0x7f98b400a310) created [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b400a310) in state Proceeding [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (779 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Record-Route: Call-ID: 0475F5859E4B8813EF379597@1070ffffffff From: "+37060960355" ;tag=Db0c.A_DY7C9_a25 To: ;tag=a357444b-4500-46fc-a7ce-95d8013af333 CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Require: 100rel RSeq: 16606 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..State changed from Proceeding to Proceeding, event=TX_MSG [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ...Transaction tsx0x7f98b40074b8 state changed to Proceeding [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:10] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg PRACK/cseq=2 (rdata0x7f9834000928) <--- Received SIP request (490 bytes) from UDP:213.102.45.36:5060 ---> PRACK sip:10.40.6.100:5060 SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=Db0c.A_DY7C9_a25 To:;tag=a357444b-4500-46fc-a7ce-95d8013af333 Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKY.6_64DVf0g43i26;yop=00.00.ACF3B0B0.0000.7010 Call-ID:0475F5859E4B8813EF379597@1070ffffffff CSeq:2 PRACK Max-Forwards:70 Request-Disposition:no-fork RAck:16606 1 INVITE Supported:timer [Nov 3 07:47:10] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:10] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:10] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:10] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:10] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4006ca8 for Request msg PRACK/cseq=2 (rdata0x7f9834000928) [Nov 3 07:47:10] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000038 on dialog dlg0x7f98b4006ca8 [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg PRACK/cseq=2 (rdata0x7f9834006a58) [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Received Request msg PRACK/cseq=2 (rdata0x7f9834006a58) [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ...Transaction created for Request msg PRACK/cseq=2 (rdata0x7f9834006a58) [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..Incoming Request msg PRACK/cseq=2 (rdata0x7f9834006a58) in state Null [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ....Transaction tsx0x7f98b401bd58 state changed to Trying [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/PRACK/cseq=2 (tdta0x7f98b401fd90) created [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f98b401fd90) [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f98b401fd90) in state Trying [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:10] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (457 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKY.6_64DVf0g43i26;yop=00.00.ACF3B0B0.0000.7010 Call-ID: 0475F5859E4B8813EF379597@1070ffffffff From: "+37060960355" ;tag=Db0c.A_DY7C9_a25 To: ;tag=a357444b-4500-46fc-a7ce-95d8013af333 CSeq: 2 PRACK Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:47:10] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ........Transaction tsx0x7f98b401bd58 state changed to Completed [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is PRACK, Response is 200 OK [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:10] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is PRACK [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : endpoint Request msg OPTIONS/cseq=14487 (tdta0x7f9834005a20) created. [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3419 endpt_send_request: 0x7f98b400c738: Wrapper created [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3436 endpt_send_request: 0x7f98b400c738: Set timer to 3000 msec [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 .Transaction created for Request msg OPTIONS/cseq=14487 (tdta0x7f9834005a20) [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 Sending Request msg OPTIONS/cseq=14487 (tdta0x7f9834005a20) in state Null [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : sip_resolve.c .Target '213.102.45.36:5060' type=UDP resolved to '213.102.45.36:5060' type=UDP (UDP transport) [Nov 3 07:47:18] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:47:18] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:18] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:18] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:18] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP request (424 bytes) to UDP:213.102.45.36:5060 ---> OPTIONS sip:213.102.45.36:5060 SIP/2.0 Via: SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj6aa45449-efa4-4f01-b294-fbd7f74ae378 From: ;tag=13949914-0430-4435-97a5-f8ea1861ed2b To: Contact: Call-ID: 78fd5852-c72d-4c67-bbb2-04e4afb1709c CSeq: 14487 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 .State changed from Null to Calling, event=TX_MSG [Nov 3 07:47:18] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=14487 (rdata0x7f9834000928) <--- Received SIP response (306 bytes) from UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Content-Length:0 From:;tag=13949914-0430-4435-97a5-f8ea1861ed2b To:;tag=dummy Via:SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj6aa45449-efa4-4f01-b294-fbd7f74ae378 Call-ID:78fd5852-c72d-4c67-bbb2-04e4afb1709c CSeq:14487 OPTIONS [Nov 3 07:47:18] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:18] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:18] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:18] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:18] DEBUG[78495]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=14487 (rdata0x7f9834000928). Using request transaction as basis [Nov 3 07:47:18] DEBUG[78495]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000010 on transaction tsx0x7f98b4024bc8 [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=14487 (rdata0x7f9834007a68) [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 .Incoming Response msg 200/OPTIONS/cseq=14487 (rdata0x7f9834007a68) in state Calling [Nov 3 07:47:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ..State changed from Calling to Completed, event=RX_MSG [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3308 endpt_send_request_cb: 0x7f98b400c738: PJSIP tsx response received [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3321 endpt_send_request_cb: 0x7f98b400c738: Cancelling timer [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3331 endpt_send_request_cb: 0x7f98b400c738: Timer cancelled [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:47:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3350 endpt_send_request_cb: 0x7f98b400c738: Callbacks executed [Nov 3 07:47:18] DEBUG[78496]: res_pjsip.c:3401 send_request_wrapper_destructor: 0x7f98b400c738: wrapper destroyed [Nov 3 07:47:18] DEBUG[78501]: res_pjsip/pjsip_configuration.c:284 persistent_endpoint_contact_status_observer: Contact t2-ossnet-2/sip:213.102.45.36:5060 status didn't change: Reachable, RTT: 0.926 msec [Nov 3 07:47:18] DEBUG[78532]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1478159238 Interval: 30 [Nov 3 07:47:18] DEBUG[78532]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [Nov 3 07:47:19] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (552 bytes) from UDP:213.102.45.36:5060 ---> CANCEL sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=Db0c.A_DY7C9_a25 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Call-ID:0475F5859E4B8813EF379597@1070ffffffff CSeq:1 CANCEL Max-Forwards:70 Route: Request-Disposition:no-fork Reason:X.int ;reasoncode=0x0000030B;add-info=0132.0001.0B2E [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:19] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg CANCEL/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:19] DEBUG[78495]: pjproject:0 : endpoint .Response msg 481/CANCEL/cseq=1 (tdta0x7f9834006a30) created [Nov 3 07:47:19] DEBUG[78495]: pjproject:0 : sip_resolve.c .Target '213.102.45.36:5060' type=UDP resolved to '213.102.45.36:5060' type=UDP (UDP transport) [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:19] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (463 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;received=213.102.45.36;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Call-ID: 0475F5859E4B8813EF379597@1070ffffffff From: "+37060960355" ;tag=Db0c.A_DY7C9_a25 To: ;tag=z9hG4bK_.C564B0e0idg_Y6 CSeq: 1 CANCEL Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:19] DEBUG[78495]: pjproject:0 : tdta0x7f983400 .Destroying txdata Response msg 481/CANCEL/cseq=1 (tdta0x7f9834006a30) [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4024 Timeout timer event [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4024 .State changed from Completed to Terminated, event=TIMER [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4024 Timeout timer event [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4024 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tdta0x7f983400 ..Destroying txdata Request msg OPTIONS/cseq=14487 (tdta0x7f9834005a20) [Nov 3 07:47:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4024 Transaction destroyed! [Nov 3 07:47:28] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (1783 bytes) from UDP:213.102.45.36:5060 ---> INVITE sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:649 From:"+37060960355" ;tag=gj20e.6gY39CDCY5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Call-ID:5D2D8EE87539E556372E1D97@0370ffffffff CSeq:1 INVITE Max-Forwards:70 Route: Record-Route: Request-Disposition:no-fork P-Asserted-Identity:, Session-Expires:1800;refresher=uac Contact: Supported:100rel,timer,norefersub Allow:ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,PRACK,REFER,UPDATE P-Charging-Vector:icid-value=c2BImQPw~~~~~~~~~~~~~wSwBIYE;icid-generated-at=213.102.45.36;orig-ioi=LTMSS2-SIP.TELE2.NET P-Early-Media:supported Content-Type:application/sdp Content-Disposition:session;handling=required v=0 o=- 0 0 IN IP4 10.20.198.213 s=- c=IN IP4 213.102.45.245 t=0 0 m=audio 63468 RTP/AVP 96 97 98 3 99 100 8 101 b=AS:80 a=rtpmap:96 AMR/8000 a=fmtp:96 mode-set=0,2,4,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:97 AMR/8000 a=fmtp:97 mode-set=0,2,5,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:98 GSM-EFR/8000 a=rtpmap:3 GSM/8000 a=rtpmap:99 AMR/8000 a=fmtp:99 mode-set=0,2,4; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:100 AMR/8000 a=fmtp:100 mode-change-capability=2; max-red=0 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=maxptime:20 [Nov 3 07:47:28] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:28] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:28] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:28] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:28] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:28] DEBUG[78495]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f9834008308) [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port ''. [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 213.102.45.36:5060 does not match identify 't2-ossnet-1' [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 213.102.45.36:5060 matches identify 't2-ossnet-2' [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint t2-ossnet-2 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7f9834008308) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b .Incoming Request msg INVITE/cseq=1 (rdata0x7f9834008308) in state Null [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ..State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ...Transaction tsx0x7f98b400bf38 state changed to Trying [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .UAS dialog created [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Module mod-invite added as dialog usage, data=0x7f98b40244e8 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ..Session count inc to 2 by mod-invite [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Module mod-100rel added as dialog usage, data=0x7f98b40102e8 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .100rel module attached [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : inv0x7f98b4024 .UAS invite session created for dialog dlg0x7f98b4024bc8 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Module Session Module added as dialog usage, data=(nil) [Nov 3 07:47:28] DEBUG[78496]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=1 (rdata0x7f9834008308) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ..Session count inc to 2 by Session Module [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:265 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.245' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.245' and port ''. [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:435 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f98b4025da8' [Nov 3 07:47:28] DEBUG[78496]: res_rtp_asterisk.c:2621 ast_rtp_new: Allocated port 14338 for RTP instance '0x7f98b4025da8' [Nov 3 07:47:28] DEBUG[78496]: res_rtp_asterisk.c:2648 ast_rtp_new: Creating ICE session 0.0.0.0:14338 (14338) for RTP instance '0x7f98b4025da8' [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : icess0x7f98b40 ICE session created, comp_cnt=2, role is Unknown agent [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha280664, addr=10.40.6.100:14338, base=10.40.6.100:14338, prio=0x7effffff (2130706431) [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:444 ast_rtp_instance_new: RTP instance '0x7f98b4025da8' is setup and ready to go [Nov 3 07:47:28] DEBUG[78496]: res_rtp_asterisk.c:4861 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f98b4025da8' [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 1 added: comp_id=2, type=host, foundation=Ha280664, addr=10.40.6.100:14339, base=10.40.6.100:14339, prio=0x7efffffe (2130706430) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Destroying ICE session 0x7f98b402d098 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4030eb8 destroy request, ref_cnt=4 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4031eb8 destroy request, ref_cnt=3 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : ice_session.c ICE session 0x7f98b402d098 destroyed [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4030eb8 destroyed [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4031eb8 destroyed [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 98 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f98b4019ce0) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f98b402da90) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x7f98b4029e00) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 98 (0x2b63a70) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 99 (0x7f98b402a390) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f98b402a420) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f98b402dbe0) from 0x7f98c14c44f0 to 0x7f98b4025f70 [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:275 handle_incoming_sdp: Media stream 'audio' handled by audio [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_t38.c:736 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7f9834005a20) created [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7f9834005a20) [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : inv0x7f98b4024 .Sending Response msg 100/INVITE/cseq=1 (tdta0x7f9834005a20) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f9834005a20) [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f9834005a20) in state Trying [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:28] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (533 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Record-Route: Call-ID: 5D2D8EE87539E556372E1D97@0370ffffffff From: "+37060960355" ;tag=gj20e.6gY39CDCY5 To: CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ...State changed from Trying to Proceeding, event=TX_MSG [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ....Transaction tsx0x7f98b400bf38 state changed to Proceeding [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b400bf38 [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:28] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is INVITE [Nov 3 07:47:28] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 Module NAT added as dialog usage, data=(nil) [Nov 3 07:47:28] DEBUG[78496]: chan_pjsip.c:2302 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/t2-ossnet-2-00000001 [Nov 3 07:47:28] DEBUG[78626][C-00000001]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:1] Wait("PJSIP/t2-ossnet-2-00000001", "1") in new stack [Nov 3 07:47:29] DEBUG[78626][C-00000001]: pbx.c:2825 pbx_extension_helper: Launching 'Ringing' -- Executing [963667366321@t2-ringing-test:2] Ringing("PJSIP/t2-ossnet-2-00000001", "") in new stack [Nov 3 07:47:29] DEBUG[78626][C-00000001]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:3] Wait("PJSIP/t2-ossnet-2-00000001", "45") in new stack [Nov 3 07:47:29] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:29] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : inv0x7f98b4024 .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f9834005a20) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Reliable response Response msg 180/INVITE/cseq=1 (tdta0x7f9834006a30) created [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f9834006a30) in state Proceeding [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (779 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Record-Route: Call-ID: 5D2D8EE87539E556372E1D97@0370ffffffff From: "+37060960355" ;tag=gj20e.6gY39CDCY5 To: ;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Require: 100rel RSeq: 28296 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ..State changed from Proceeding to Proceeding, event=TX_MSG [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ...Transaction tsx0x7f98b400bf38 state changed to Proceeding [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b400bf38 [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:29] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg PRACK/cseq=2 (rdata0x7f9834000928) <--- Received SIP request (490 bytes) from UDP:213.102.45.36:5060 ---> PRACK sip:10.40.6.100:5060 SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=gj20e.6gY39CDCY5 To:;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKA7hUfg8adD5d_f26;yop=00.00.ACF3B0B0.0000.7003 Call-ID:5D2D8EE87539E556372E1D97@0370ffffffff CSeq:2 PRACK Max-Forwards:70 Request-Disposition:no-fork RAck:28296 1 INVITE Supported:timer [Nov 3 07:47:29] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:29] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:29] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:29] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:29] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4024bc8 for Request msg PRACK/cseq=2 (rdata0x7f9834000928) [Nov 3 07:47:29] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000021 on dialog dlg0x7f98b4024bc8 [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg PRACK/cseq=2 (rdata0x7f9834008e58) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Received Request msg PRACK/cseq=2 (rdata0x7f9834008e58) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 ...Transaction created for Request msg PRACK/cseq=2 (rdata0x7f9834008e58) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 ..Incoming Request msg PRACK/cseq=2 (rdata0x7f9834008e58) in state Null [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ....Transaction tsx0x7f98b40233a8 state changed to Trying [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/PRACK/cseq=2 (tdta0x7f98b4036f00) created [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f98b4036f00) [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f98b4036f00) in state Trying [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:29] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (457 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKA7hUfg8adD5d_f26;yop=00.00.ACF3B0B0.0000.7003 Call-ID: 5D2D8EE87539E556372E1D97@0370ffffffff From: "+37060960355" ;tag=gj20e.6gY39CDCY5 To: ;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 CSeq: 2 PRACK Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:47:29] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ........Transaction tsx0x7f98b40233a8 state changed to Completed [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b40233a8 [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is PRACK, Response is 200 OK [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b40233a8 [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:29] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is PRACK [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : endpoint Request msg OPTIONS/cseq=53136 (tdta0x7f9834007e20) created. [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3419 endpt_send_request: 0x7f98b4022d48: Wrapper created [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3436 endpt_send_request: 0x7f98b4022d48: Set timer to 3000 msec [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c .Transaction created for Request msg OPTIONS/cseq=53136 (tdta0x7f9834007e20) [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c Sending Request msg OPTIONS/cseq=53136 (tdta0x7f9834007e20) in state Null [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : sip_resolve.c .Target '213.102.44.36:5060' type=UDP resolved to '213.102.44.36:5060' type=UDP (UDP transport) [Nov 3 07:47:32] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:47:32] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:32] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:32] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.44.36:5060' into... [Nov 3 07:47:32] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.44.36' and port '5060'. <--- Transmitting SIP request (424 bytes) to UDP:213.102.44.36:5060 ---> OPTIONS sip:213.102.44.36:5060 SIP/2.0 Via: SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPjba97ee31-6bb6-451d-a369-5faede43ebfe From: ;tag=19f18ba7-c19e-40c7-9da9-9609d12a3b3f To: Contact: Call-ID: 47c0faf4-7507-4906-b729-9e24a0e4972c CSeq: 53136 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c .State changed from Null to Calling, event=TX_MSG [Nov 3 07:47:32] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=53136 (rdata0x7f9834000928) <--- Received SIP response (306 bytes) from UDP:213.102.44.36:5060 ---> SIP/2.0 200 OK Content-Length:0 From:;tag=19f18ba7-c19e-40c7-9da9-9609d12a3b3f To:;tag=dummy Via:SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPjba97ee31-6bb6-451d-a369-5faede43ebfe Call-ID:47c0faf4-7507-4906-b729-9e24a0e4972c CSeq:53136 OPTIONS [Nov 3 07:47:32] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.44.36:5060' into... [Nov 3 07:47:32] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.44.36' and port '5060'. [Nov 3 07:47:32] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:32] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:32] DEBUG[78495]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=53136 (rdata0x7f9834000928). Using request transaction as basis [Nov 3 07:47:32] DEBUG[78495]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000009 on transaction tsx0x7f98b403cc48 [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=53136 (rdata0x7f9834009e68) [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c .Incoming Response msg 200/OPTIONS/cseq=53136 (rdata0x7f9834009e68) in state Calling [Nov 3 07:47:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c ..State changed from Calling to Completed, event=RX_MSG [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3308 endpt_send_request_cb: 0x7f98b4022d48: PJSIP tsx response received [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3321 endpt_send_request_cb: 0x7f98b4022d48: Cancelling timer [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3331 endpt_send_request_cb: 0x7f98b4022d48: Timer cancelled [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:47:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3350 endpt_send_request_cb: 0x7f98b4022d48: Callbacks executed [Nov 3 07:47:32] DEBUG[78496]: res_pjsip.c:3401 send_request_wrapper_destructor: 0x7f98b4022d48: wrapper destroyed [Nov 3 07:47:32] DEBUG[78501]: res_pjsip/pjsip_configuration.c:284 persistent_endpoint_contact_status_observer: Contact t2-ossnet-1/sip:213.102.44.36:5060 status didn't change: Reachable, RTT: 0.903 msec [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (552 bytes) from UDP:213.102.45.36:5060 ---> CANCEL sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=gj20e.6gY39CDCY5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Call-ID:5D2D8EE87539E556372E1D97@0370ffffffff CSeq:1 CANCEL Max-Forwards:70 Route: Request-Disposition:no-fork Reason:X.int ;reasoncode=0x0000030B;add-info=0132.0001.0B2E [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:37] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4024bc8 for Request msg CANCEL/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:37] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000021 on dialog dlg0x7f98b4024bc8 [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Received Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b4028 ...Transaction created for Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b4028 ..Incoming Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) in state Null [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b4028 ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ....Transaction tsx0x7f98b4028758 state changed to Trying [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b4028758 [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Trying [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is CANCEL [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/CANCEL/cseq=1 (tdta0x7f98b40405a0) created [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ......Sending Response msg 200/CANCEL/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b4028 ......Sending Response msg 200/CANCEL/cseq=1 (tdta0x7f98b40405a0) in state Trying [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (458 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Call-ID: 5D2D8EE87539E556372E1D97@0370ffffffff From: "+37060960355" ;tag=gj20e.6gY39CDCY5 To: ;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 CSeq: 1 CANCEL Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b4028 .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ........Transaction tsx0x7f98b4028758 state changed to Completed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b4028758 [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is CANCEL, Response is 200 OK [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .....Reliable response Response msg 487/INVITE/cseq=1 (tdta0x7f98b4043cc0) created [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ......Sending Response msg 487/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ......Sending Response msg 487/INVITE/cseq=1 (tdta0x7f98b4043cc0) in state Proceeding [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tdta0x7f983400 .......Destroying txdata Response msg 487/INVITE/cseq=1 (tdta0x7f9834006a30) [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:37] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (757 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Record-Route: Call-ID: 5D2D8EE87539E556372E1D97@0370ffffffff From: "+37060960355" ;tag=gj20e.6gY39CDCY5 To: ;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Server: Asterisk PBX 13.11.2 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b .......State changed from Proceeding to Completed, event=TX_MSG [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ........Transaction tsx0x7f98b400bf38 state changed to Completed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ..........Session count dec to 6 by mod-invite [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000001)' [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b400bf38 [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated [Nov 3 07:47:37] DEBUG[78626][C-00000001]: pbx.c:4296 __ast_pbx_run: Spawn extension (t2-ringing-test,963667366321,3) exited non-zero on 'PJSIP/t2-ossnet-2-00000001' == Spawn extension (t2-ringing-test, 963667366321, 3) exited non-zero on 'PJSIP/t2-ossnet-2-00000001' [Nov 3 07:47:37] DEBUG[78626][C-00000001]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/t2-ossnet-2-00000001' [Nov 3 07:47:37] DEBUG[78626][C-00000001]: channel.c:2683 ast_hangup: Hanging up channel 'PJSIP/t2-ossnet-2-00000001' [Nov 3 07:47:37] DEBUG[78484]: cdr.c:1277 cdr_object_finalize: Finalized CDR for PJSIP/t2-ossnet-2-00000001 - start 1478159248.201365 answer 0.000000 end 1478159257.232241 dispo NO ANSWER [Nov 3 07:47:37] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:47:37] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:47:37] DEBUG[78484]: cdr.c:3262 post_cdr: Skipping CDR for PJSIP/t2-ossnet-2-00000001 since we weren't answered [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (497 bytes) from UDP:213.102.45.36:5060 ---> ACK sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=gj20e.6gY39CDCY5 To:;tag=327857a5-d9f4-448b-b12f-70d6010f2a58 Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKBgj4feBg7j5e4026;yop=00.00.ACF3B0B0.0000.7003 Call-ID:5D2D8EE87539E556372E1D97@0370ffffffff CSeq:1 ACK Max-Forwards:70 Route: [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:37] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:37] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4024bc8 for Request msg ACK/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:37] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000021 on dialog dlg0x7f98b4024bc8 [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f983400a248) [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b .Incoming Request msg ACK/cseq=1 (rdata0x7f983400a248) in state Completed [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tsx0x7f98b400b ..State changed from Completed to Confirmed, event=RX_MSG [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 ...Transaction tsx0x7f98b400bf38 state changed to Confirmed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b400bf38) [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b400bf38 [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Confirmed [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:37] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is ACK [Nov 3 07:47:37] DEBUG[78496]: pjproject:0 : tdta0x7f983400 ....Destroying txdata Response msg 180/INVITE/cseq=1 (tdta0x7f9834005a20) [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Timeout timer event [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c .State changed from Completed to Terminated, event=TIMER [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Timeout timer event [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tdta0x7f983400 ..Destroying txdata Request msg OPTIONS/cseq=53136 (tdta0x7f9834007e20) [Nov 3 07:47:37] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Transaction destroyed! [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Timeout timer event [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b .State changed from Completed to Terminated, event=TIMER [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : dlg0x7f98b4006 ..Transaction tsx0x7f98b401bd58 state changed to Terminated [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Timeout timer event [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tdta0x7f98b401 ..Destroying txdata Response msg 200/PRACK/cseq=2 (tdta0x7f98b401fd90) [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Transaction destroyed! [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b400b Timeout timer event [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b400b .State changed from Confirmed to Terminated, event=TIMER [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : dlg0x7f98b4024 ..Transaction tsx0x7f98b400bf38 state changed to Terminated [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b400bf38 [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:47:42] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b400b Timeout timer event [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b400b .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tdta0x7f98b404 ..Destroying txdata Response msg 487/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:42] DEBUG[78495]: pjproject:0 : tsx0x7f98b400b Transaction destroyed! [Nov 3 07:47:42] DEBUG[78496]: res_pjsip_session.c:1318 session_destructor: Destroying SIP session with endpoint t2-ossnet-2 [Nov 3 07:47:42] DEBUG[78496]: res_rtp_asterisk.c:4917 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f98b4025da8' [Nov 3 07:47:42] DEBUG[78496]: rtp_engine.c:378 instance_destructor: Destroyed RTP instance '0x7f98b4025da8' [Nov 3 07:47:42] DEBUG[78496]: pjproject:0 : dlg0x7f98b4024 .Session count dec to 0 by Session Module [Nov 3 07:47:45] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (1783 bytes) from UDP:213.102.45.36:5060 ---> INVITE sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:649 From:"+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Call-ID:86DB7F42130158F785A20397@0c70ffffffff CSeq:1 INVITE Max-Forwards:70 Route: Record-Route: Request-Disposition:no-fork P-Asserted-Identity:, Session-Expires:1800;refresher=uac Contact: Supported:100rel,timer,norefersub Allow:ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,PRACK,REFER,UPDATE P-Charging-Vector:icid-value=c2BImQPw~~~~~~~~~~~~~wS7DYYE;icid-generated-at=213.102.45.36;orig-ioi=LTMSS2-SIP.TELE2.NET P-Early-Media:supported Content-Type:application/sdp Content-Disposition:session;handling=required v=0 o=- 0 0 IN IP4 10.20.198.213 s=- c=IN IP4 213.102.45.244 t=0 0 m=audio 27914 RTP/AVP 96 97 98 3 99 100 8 101 b=AS:80 a=rtpmap:96 AMR/8000 a=fmtp:96 mode-set=0,2,4,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:97 AMR/8000 a=fmtp:97 mode-set=0,2,5,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:98 GSM-EFR/8000 a=rtpmap:3 GSM/8000 a=rtpmap:99 AMR/8000 a=fmtp:99 mode-set=0,2,4; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:100 AMR/8000 a=fmtp:100 mode-change-capability=2; max-red=0 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=maxptime:20 [Nov 3 07:47:45] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:45] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:45] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:45] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:45] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:45] DEBUG[78495]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000036 to use for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port ''. [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 213.102.45.36:5060 does not match identify 't2-ossnet-1' [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 213.102.45.36:5060 matches identify 't2-ossnet-2' [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint t2-ossnet-2 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .Incoming Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) in state Null [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ...Transaction tsx0x7f98b401bd58 state changed to Trying [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .UAS dialog created [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Module mod-invite added as dialog usage, data=0x7f98b4031988 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ..Session count inc to 2 by mod-invite [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Module mod-100rel added as dialog usage, data=0x7f98b4032598 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .100rel module attached [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : inv0x7f98b400b .UAS invite session created for dialog dlg0x7f98b400bf38 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Module Session Module added as dialog usage, data=(nil) [Nov 3 07:47:45] DEBUG[78496]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000036 to use for Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ..Session count inc to 2 by Session Module [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:265 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.244' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.244' and port ''. [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:435 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f98b401c938' [Nov 3 07:47:45] DEBUG[78496]: res_rtp_asterisk.c:2621 ast_rtp_new: Allocated port 12098 for RTP instance '0x7f98b401c938' [Nov 3 07:47:45] DEBUG[78496]: res_rtp_asterisk.c:2648 ast_rtp_new: Creating ICE session 0.0.0.0:12098 (12098) for RTP instance '0x7f98b401c938' [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : icess0x7f98b40 ICE session created, comp_cnt=2, role is Unknown agent [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha280664, addr=10.40.6.100:12098, base=10.40.6.100:12098, prio=0x7effffff (2130706431) [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:444 ast_rtp_instance_new: RTP instance '0x7f98b401c938' is setup and ready to go [Nov 3 07:47:45] DEBUG[78496]: res_rtp_asterisk.c:4861 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f98b401c938' [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 1 added: comp_id=2, type=host, foundation=Ha280664, addr=10.40.6.100:12099, base=10.40.6.100:12099, prio=0x7efffffe (2130706430) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Destroying ICE session 0x7f98b402da98 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b403ae38 destroy request, ref_cnt=4 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4025d78 destroy request, ref_cnt=3 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : ice_session.c ICE session 0x7f98b402da98 destroyed [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b403ae38 destroyed [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4025d78 destroyed [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 98 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f98c14c44f0 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f98b4036c70) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f98b4043c70) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x7f98b4005760) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 98 (0x2b63a70) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 99 (0x7f98b4023c70) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f98b4043c30) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f98b4032130) from 0x7f98c14c44f0 to 0x7f98b401cb00 [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:275 handle_incoming_sdp: Media stream 'audio' handled by audio [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_t38.c:736 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7f98b4043cc0) created [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : inv0x7f98b400b .Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b4043cc0) in state Trying [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:45] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (533 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Record-Route: Call-ID: 86DB7F42130158F785A20397@0c70ffffffff From: "+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ...State changed from Trying to Proceeding, event=TX_MSG [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ....Transaction tsx0x7f98b401bd58 state changed to Proceeding [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:47:45] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is INVITE [Nov 3 07:47:45] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b Module NAT added as dialog usage, data=(nil) [Nov 3 07:47:45] DEBUG[78496]: chan_pjsip.c:2302 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/t2-ossnet-2-00000002 [Nov 3 07:47:45] DEBUG[78627][C-00000002]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:1] Wait("PJSIP/t2-ossnet-2-00000002", "1") in new stack [Nov 3 07:47:46] DEBUG[78627][C-00000002]: pbx.c:2825 pbx_extension_helper: Launching 'Ringing' -- Executing [963667366321@t2-ringing-test:2] Ringing("PJSIP/t2-ossnet-2-00000002", "") in new stack [Nov 3 07:47:46] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:47:46] DEBUG[78627][C-00000002]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:3] Wait("PJSIP/t2-ossnet-2-00000002", "45") in new stack [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:46] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : inv0x7f98b400b .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Reliable response Response msg 180/INVITE/cseq=1 (tdta0x7f98b401fd90) created [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b401fd90) in state Proceeding [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (779 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Record-Route: Call-ID: 86DB7F42130158F785A20397@0c70ffffffff From: "+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: ;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Require: 100rel RSeq: 19595 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..State changed from Proceeding to Proceeding, event=TX_MSG [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ...Transaction tsx0x7f98b401bd58 state changed to Proceeding [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:47:46] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg PRACK/cseq=2 (rdata0x7f9834000928) <--- Received SIP request (490 bytes) from UDP:213.102.45.36:5060 ---> PRACK sip:10.40.6.100:5060 SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=h7gU_dChZ5B4cgg5 To:;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bK4AVbhb20W131d.Y6;yop=00.00.ACF3B0B0.0000.700C Call-ID:86DB7F42130158F785A20397@0c70ffffffff CSeq:2 PRACK Max-Forwards:70 Request-Disposition:no-fork RAck:19595 1 INVITE Supported:timer [Nov 3 07:47:46] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:46] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:46] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:46] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:46] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b400bf38 for Request msg PRACK/cseq=2 (rdata0x7f9834000928) [Nov 3 07:47:46] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000036 on dialog dlg0x7f98b400bf38 [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Received Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c ...Transaction created for Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c ..Incoming Request msg PRACK/cseq=2 (rdata0x7f9834009e68) in state Null [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ....Transaction tsx0x7f98b403cc48 state changed to Trying [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/PRACK/cseq=2 (tdta0x7f9834008e30) created [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f9834008e30) [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f9834008e30) in state Trying [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:46] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (457 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bK4AVbhb20W131d.Y6;yop=00.00.ACF3B0B0.0000.700C Call-ID: 86DB7F42130158F785A20397@0c70ffffffff From: "+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: ;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b CSeq: 2 PRACK Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : tsx0x7f98b403c .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:47:46] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ........Transaction tsx0x7f98b403cc48 state changed to Completed [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b403cc48 [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is PRACK, Response is 200 OK [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b403cc48 [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:46] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is PRACK [Nov 3 07:47:48] DEBUG[78532]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1478159268 Interval: 30 [Nov 3 07:47:48] DEBUG[78532]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts -- Auto fallthrough, channel 'PJSIP/t2-ossnet-2-00000000' status is 'UNKNOWN' [Nov 3 07:47:55] DEBUG[78622][C-00000000]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/t2-ossnet-2-00000000' [Nov 3 07:47:55] DEBUG[78622][C-00000000]: channel.c:2683 ast_hangup: Hanging up channel 'PJSIP/t2-ossnet-2-00000000' [Nov 3 07:47:55] DEBUG[78622][C-00000000]: chan_pjsip.c:1804 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP) [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 603 Decline [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : inv0x7f98b4006 .Sending Response msg 603/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Reliable response Response msg 603/INVITE/cseq=1 (tdta0x7f9834007e20) created [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ..Sending Response msg 603/INVITE/cseq=1 (tdta0x7f9834007e20) [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..Sending Response msg 603/INVITE/cseq=1 (tdta0x7f9834007e20) in state Proceeding [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tdta0x7f98b400 ...Destroying txdata Response msg 180/INVITE/cseq=1 (tdta0x7f98b400a310) [Nov 3 07:47:55] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:55] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:55] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:55] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (739 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 603 Decline Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Record-Route: Call-ID: 0475F5859E4B8813EF379597@1070ffffffff From: "+37060960355" ;tag=Db0c.A_DY7C9_a25 To: ;tag=a357444b-4500-46fc-a7ce-95d8013af333 CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=0 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ...State changed from Proceeding to Completed, event=TX_MSG [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ....Transaction tsx0x7f98b40074b8 state changed to Completed [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 603 Decline [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ......Session count dec to 3 by mod-invite [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000000)' [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b40074b8) [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 603 Decline [Nov 3 07:47:55] DEBUG[78484]: cdr.c:1277 cdr_object_finalize: Finalized CDR for PJSIP/t2-ossnet-2-00000000 - start 1478159229.058134 answer 0.000000 end 1478159275.103518 dispo FAILED [Nov 3 07:47:55] DEBUG[78484]: cdr.c:3262 post_cdr: Skipping CDR for PJSIP/t2-ossnet-2-00000000 since we weren't answered [Nov 3 07:47:55] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:47:55] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:47:55] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (497 bytes) from UDP:213.102.45.36:5060 ---> ACK sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=Db0c.A_DY7C9_a25 To:;tag=a357444b-4500-46fc-a7ce-95d8013af333 Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bK_.C564B0e0idg_Y6;yop=00.00.ACF3B0B0.0000.7010 Call-ID:0475F5859E4B8813EF379597@1070ffffffff CSeq:1 ACK Max-Forwards:70 Route: [Nov 3 07:47:55] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:55] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:55] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:55] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:55] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4006ca8 for Request msg ACK/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:55] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000038 on dialog dlg0x7f98b4006ca8 [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 .Received Request msg ACK/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..Request to terminate transaction [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ...State changed from Completed to Terminated, event=USER [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : dlg0x7f98b4006 ....Transaction tsx0x7f98b40074b8 state changed to Terminated [Nov 3 07:47:55] DEBUG[78496]: pjproject:0 : tdta0x7f98b400 .....Destroying txdata Response msg 603/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is USER [Nov 3 07:47:55] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:55] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 Timeout timer event [Nov 3 07:47:55] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:47:55] DEBUG[78495]: pjproject:0 : tdta0x7f983400 ..Destroying txdata Response msg 603/INVITE/cseq=1 (tdta0x7f9834007e20) [Nov 3 07:47:55] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 Transaction destroyed! [Nov 3 07:47:58] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (552 bytes) from UDP:213.102.45.36:5060 ---> CANCEL sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Call-ID:86DB7F42130158F785A20397@0c70ffffffff CSeq:1 CANCEL Max-Forwards:70 Route: Request-Disposition:no-fork Reason:X.int ;reasoncode=0x0000030B;add-info=0132.0001.0B2E [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:58] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b400bf38 for Request msg CANCEL/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:58] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000036 on dialog dlg0x7f98b400bf38 [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Received Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ...Transaction created for Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..Incoming Request msg CANCEL/cseq=1 (rdata0x7f9834009e68) in state Null [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ....Transaction tsx0x7f98b40074b8 state changed to Trying [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Trying [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is CANCEL [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/CANCEL/cseq=1 (tdta0x7f98b400a310) created [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ......Sending Response msg 200/CANCEL/cseq=1 (tdta0x7f98b400a310) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ......Sending Response msg 200/CANCEL/cseq=1 (tdta0x7f98b400a310) in state Trying [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (458 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Call-ID: 86DB7F42130158F785A20397@0c70ffffffff From: "+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: ;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b CSeq: 1 CANCEL Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ........Transaction tsx0x7f98b40074b8 state changed to Completed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is CANCEL, Response is 200 OK [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .....Reliable response Response msg 487/INVITE/cseq=1 (tdta0x7f98b40057c0) created [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ......Sending Response msg 487/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ......Sending Response msg 487/INVITE/cseq=1 (tdta0x7f98b40057c0) in state Proceeding [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tdta0x7f98b401 .......Destroying txdata Response msg 487/INVITE/cseq=1 (tdta0x7f98b401fd90) [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:58] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (757 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Record-Route: Call-ID: 86DB7F42130158F785A20397@0c70ffffffff From: "+37060960355" ;tag=h7gU_dChZ5B4cgg5 To: ;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Server: Asterisk PBX 13.11.2 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .......State changed from Proceeding to Completed, event=TX_MSG [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ........Transaction tsx0x7f98b401bd58 state changed to Completed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ..........Session count dec to 6 by mod-invite [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000002)' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:47:58] DEBUG[78627][C-00000002]: pbx.c:4296 __ast_pbx_run: Spawn extension (t2-ringing-test,963667366321,3) exited non-zero on 'PJSIP/t2-ossnet-2-00000002' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated == Spawn extension (t2-ringing-test, 963667366321, 3) exited non-zero on 'PJSIP/t2-ossnet-2-00000002' [Nov 3 07:47:58] DEBUG[78627][C-00000002]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/t2-ossnet-2-00000002' [Nov 3 07:47:58] DEBUG[78627][C-00000002]: channel.c:2683 ast_hangup: Hanging up channel 'PJSIP/t2-ossnet-2-00000002' [Nov 3 07:47:58] DEBUG[78484]: cdr.c:1277 cdr_object_finalize: Finalized CDR for PJSIP/t2-ossnet-2-00000002 - start 1478159265.804778 answer 0.000000 end 1478159278.265795 dispo NO ANSWER [Nov 3 07:47:58] DEBUG[78484]: cdr.c:3262 post_cdr: Skipping CDR for PJSIP/t2-ossnet-2-00000002 since we weren't answered [Nov 3 07:47:58] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:47:58] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 1 (Not in use) [Nov 3 07:47:58] DEBUG[78546]: app_queue.c:2477 device_state_cb: Device 'PJSIP/t2-ossnet-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 3 07:47:58] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (497 bytes) from UDP:213.102.45.36:5060 ---> ACK sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=h7gU_dChZ5B4cgg5 To:;tag=daa8fcb4-35e3-41a5-bcd8-20670b0d2d3b Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKiC76haW08X5Cc226;yop=00.00.ACF3B0B0.0000.700C Call-ID:86DB7F42130158F785A20397@0c70ffffffff CSeq:1 ACK Max-Forwards:70 Route: [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:47:58] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:47:58] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b400bf38 for Request msg ACK/cseq=1 (rdata0x7f9834000928) [Nov 3 07:47:58] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000036 on dialog dlg0x7f98b400bf38 [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f9834009e68) [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .Incoming Request msg ACK/cseq=1 (rdata0x7f9834009e68) in state Completed [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..State changed from Completed to Confirmed, event=RX_MSG [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b ...Transaction tsx0x7f98b401bd58 state changed to Confirmed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b401bd58) [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Confirmed [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:47:58] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is ACK [Nov 3 07:47:58] DEBUG[78496]: pjproject:0 : tdta0x7f98b404 ....Destroying txdata Response msg 180/INVITE/cseq=1 (tdta0x7f98b4043cc0) [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Timeout timer event [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 .State changed from Completed to Terminated, event=TIMER [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : dlg0x7f98b4024 ..Transaction tsx0x7f98b40233a8 state changed to Terminated [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2343 __print_debug_details: inv_session 0x7f98b40244e8 has no ast session [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b40233a8 [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:48:01] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Timeout timer event [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tdta0x7f98b403 ..Destroying txdata Response msg 200/PRACK/cseq=2 (tdta0x7f98b4036f00) [Nov 3 07:48:01] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Transaction destroyed! [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Timeout timer event [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b .State changed from Confirmed to Terminated, event=TIMER [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : dlg0x7f98b400b ..Transaction tsx0x7f98b401bd58 state changed to Terminated [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:48:03] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:48:03] DEBUG[78496]: res_pjsip_session.c:1318 session_destructor: Destroying SIP session with endpoint t2-ossnet-2 [Nov 3 07:48:03] DEBUG[78496]: res_rtp_asterisk.c:4917 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f98b401c938' [Nov 3 07:48:03] DEBUG[78496]: rtp_engine.c:378 instance_destructor: Destroyed RTP instance '0x7f98b401c938' [Nov 3 07:48:03] DEBUG[78496]: pjproject:0 : dlg0x7f98b400b .Session count dec to 0 by Session Module [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Timeout timer event [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tdta0x7f98b400 ..Destroying txdata Response msg 487/INVITE/cseq=1 (tdta0x7f98b40057c0) [Nov 3 07:48:03] DEBUG[78495]: pjproject:0 : tsx0x7f98b401b Transaction destroyed! [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tsx0x7f98b4028 Timeout timer event [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tsx0x7f98b4028 .State changed from Completed to Terminated, event=TIMER [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : dlg0x7f98b4024 ..Transaction tsx0x7f98b4028758 state changed to Terminated [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2343 __print_debug_details: inv_session 0x7f98b40244e8 has no ast session [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b4028758 [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:48:09] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : dlg0x7f98b4024 ...Dialog destroyed [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tsx0x7f98b4028 Timeout timer event [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tsx0x7f98b4028 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tdta0x7f98b404 ..Destroying txdata Response msg 200/CANCEL/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:48:09] DEBUG[78495]: pjproject:0 : tsx0x7f98b4028 Transaction destroyed! SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> SMEX-MEDIA-A1*CLI> [Nov 3 07:48:16] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (1782 bytes) from UDP:213.102.45.36:5060 ---> INVITE sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:648 From:"+37060960355" ;tag=0_iX9hYVV00AYhY5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKa_.D22ZYAjgaeh26;yop=00.00.ACF3B0B0.0000.700E Call-ID:FA1DDBAFFDB6F520E74B1197@0e70ffffffff CSeq:1 INVITE Max-Forwards:70 Route: Record-Route: Request-Disposition:no-fork P-Asserted-Identity:, Session-Expires:1800;refresher=uac Contact: Supported:100rel,timer,norefersub Allow:ACK,BYE,CANCEL,INFO,INVITE,NOTIFY,OPTIONS,PRACK,REFER,UPDATE P-Charging-Vector:icid-value=c2BImQPw~~~~~~~~~~~~~wS5HYYE;icid-generated-at=213.102.45.36;orig-ioi=LTMSS2-SIP.TELE2.NET P-Early-Media:supported Content-Type:application/sdp Content-Disposition:session;handling=required v=0 o=- 0 0 IN IP4 10.20.198.196 s=- c=IN IP4 213.102.44.244 t=0 0 m=audio 7262 RTP/AVP 96 97 98 3 99 100 8 101 b=AS:80 a=rtpmap:96 AMR/8000 a=fmtp:96 mode-set=0,2,4,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:97 AMR/8000 a=fmtp:97 mode-set=0,2,5,7; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:98 GSM-EFR/8000 a=rtpmap:3 GSM/8000 a=rtpmap:99 AMR/8000 a=fmtp:99 mode-set=0,2,4; mode-change-period=2; mode-change-neighbor=1; max-red=0 a=rtpmap:100 AMR/8000 a=fmtp:100 mode-change-capability=2; max-red=0 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=maxptime:20 [Nov 3 07:48:16] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:16] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:48:16] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:16] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:16] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:48:16] DEBUG[78495]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg INVITE/cseq=1 (rdata0x7f9834000928) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port ''. [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 213.102.45.36:5060 does not match identify 't2-ossnet-1' [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 213.102.45.36:5060 matches identify 't2-ossnet-2' [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint t2-ossnet-2 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 .Incoming Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) in state Null [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ..State changed from Null to Trying, event=RX_MSG [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ...Transaction tsx0x7f98b4024bc8 state changed to Trying [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .UAS dialog created [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Module mod-invite added as dialog usage, data=0x7f98b4043938 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ..Session count inc to 2 by mod-invite [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Module mod-100rel added as dialog usage, data=0x7f98b401bb88 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .100rel module attached [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : inv0x7f98b4028 .UAS invite session created for dialog dlg0x7f98b4028758 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Module Session Module added as dialog usage, data=(nil) [Nov 3 07:48:16] DEBUG[78496]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000026 to use for Request msg INVITE/cseq=1 (rdata0x7f983400a6e8) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ..Session count inc to 2 by Session Module [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:265 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.44.244' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.44.244' and port ''. [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:435 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f98b4033288' [Nov 3 07:48:16] DEBUG[78496]: res_rtp_asterisk.c:2621 ast_rtp_new: Allocated port 19524 for RTP instance '0x7f98b4033288' [Nov 3 07:48:16] DEBUG[78496]: res_rtp_asterisk.c:2648 ast_rtp_new: Creating ICE session 0.0.0.0:19524 (19524) for RTP instance '0x7f98b4033288' [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : icess0x7f98b40 ICE session created, comp_cnt=2, role is Unknown agent [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha280664, addr=10.40.6.100:19524, base=10.40.6.100:19524, prio=0x7effffff (2130706431) [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:444 ast_rtp_instance_new: RTP instance '0x7f98b4033288' is setup and ready to go [Nov 3 07:48:16] DEBUG[78496]: res_rtp_asterisk.c:4861 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f98b4033288' [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port ''. [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Candidate 1 added: comp_id=2, type=host, foundation=Ha280664, addr=10.40.6.100:19525, base=10.40.6.100:19525, prio=0x7efffffe (2130706430) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : icess0x7f98b40 Destroying ICE session 0x7f98b4046c48 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b4031b98 destroy request, ref_cnt=4 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : stuse0x7f98b40 STUN session 0x7f98b40193c8 destroy request, ref_cnt=3 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : ice_session.c ICE session 0x7f98b4046c48 destroyed [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b4031b98 destroyed [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : stun_session.c STUN session 0x7f98b40193c8 destroyed [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 98 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:670 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f98c14c44f0 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f98b4016130) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f98b400c780) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x7f98b400a1a0) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 98 (0x2b63a70) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 99 (0x7f98b4005760) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f98b400c740) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: rtp_engine.c:639 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f98b4043c50) from 0x7f98c14c44f0 to 0x7f98b4033450 [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:275 handle_incoming_sdp: Media stream 'audio' handled by audio [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_t38.c:736 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7f98b40405a0) created [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : inv0x7f98b4028 .Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f98b40405a0) in state Trying [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:16] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (533 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKa_.D22ZYAjgaeh26;yop=00.00.ACF3B0B0.0000.700E Record-Route: Call-ID: FA1DDBAFFDB6F520E74B1197@0e70ffffffff From: "+37060960355" ;tag=0_iX9hYVV00AYhY5 To: CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ...State changed from Trying to Proceeding, event=TX_MSG [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ....Transaction tsx0x7f98b4024bc8 state changed to Proceeding [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2()' [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b4024bc8 [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is INCOMING [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Nov 3 07:48:16] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is INVITE [Nov 3 07:48:16] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 Module NAT added as dialog usage, data=(nil) [Nov 3 07:48:16] DEBUG[78496]: chan_pjsip.c:2302 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/t2-ossnet-2-00000003 [Nov 3 07:48:16] DEBUG[78628][C-00000003]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:1] Wait("PJSIP/t2-ossnet-2-00000003", "1") in new stack [Nov 3 07:48:17] DEBUG[78628][C-00000003]: pbx.c:2825 pbx_extension_helper: Launching 'Ringing' -- Executing [963667366321@t2-ringing-test:2] Ringing("PJSIP/t2-ossnet-2-00000003", "") in new stack [Nov 3 07:48:17] DEBUG[78628][C-00000003]: pbx.c:2825 pbx_extension_helper: Launching 'Wait' -- Executing [963667366321@t2-ringing-test:3] Wait("PJSIP/t2-ossnet-2-00000003", "45") in new stack [Nov 3 07:48:17] DEBUG[78483]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - t2-ossnet-2 [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:48:17] DEBUG[78483]: devicestate.c:474 do_state_change: Changing state for PJSIP/t2-ossnet-2 - state 2 (In use) [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : inv0x7f98b4028 .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b40405a0) [Nov 3 07:48:17] DEBUG[78546]: app_queue.c:2477 device_state_cb: Device 'PJSIP/t2-ossnet-2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Reliable response Response msg 180/INVITE/cseq=1 (tdta0x7f98b40057c0) created [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 .Sending Response msg 180/INVITE/cseq=1 (tdta0x7f98b40057c0) in state Proceeding [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (778 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bKa_.D22ZYAjgaeh26;yop=00.00.ACF3B0B0.0000.700E Record-Route: Call-ID: FA1DDBAFFDB6F520E74B1197@0e70ffffffff From: "+37060960355" ;tag=0_iX9hYVV00AYhY5 To: ;tag=29e0efc9-df1d-4fe8-b7f5-7d720cfd9e86 CSeq: 1 INVITE Server: Asterisk PBX 13.11.2 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Require: 100rel RSeq: 9167 Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b4024 ..State changed from Proceeding to Proceeding, event=TX_MSG [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ...Transaction tsx0x7f98b4024bc8 state changed to Proceeding [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000003)' [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2365 __print_debug_details: There is no transaction involved in this state change [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2552 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000003)' [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f98b4024bc8 [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Proceeding [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Nov 3 07:48:17] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg PRACK/cseq=2 (rdata0x7f9834000928) <--- Received SIP request (489 bytes) from UDP:213.102.45.36:5060 ---> PRACK sip:10.40.6.100:5060 SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=0_iX9hYVV00AYhY5 To:;tag=29e0efc9-df1d-4fe8-b7f5-7d720cfd9e86 Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bK00Z527W6ebiabUY6;yop=00.00.ACF3B0B0.0000.700E Call-ID:FA1DDBAFFDB6F520E74B1197@0e70ffffffff CSeq:2 PRACK Max-Forwards:70 Request-Disposition:no-fork RAck:9167 1 INVITE Supported:timer [Nov 3 07:48:17] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:17] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:48:17] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:17] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:17] DEBUG[78495]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f98b4028758 for Request msg PRACK/cseq=2 (rdata0x7f9834000928) [Nov 3 07:48:17] DEBUG[78495]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000026 on dialog dlg0x7f98b4028758 [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 .Received Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ...Transaction created for Request msg PRACK/cseq=2 (rdata0x7f9834009e68) [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ..Incoming Request msg PRACK/cseq=2 (rdata0x7f9834009e68) in state Null [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ...State changed from Null to Trying, event=RX_MSG [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ....Transaction tsx0x7f98b401bd58 state changed to Trying [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : endpoint .....Response msg 200/PRACK/cseq=2 (tdta0x7f9834007e20) created [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f9834007e20) [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b ......Sending Response msg 200/PRACK/cseq=2 (tdta0x7f9834007e20) in state Trying [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:17] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (457 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;rport=5060;received=213.102.45.36;branch=z9hG4bK00Z527W6ebiabUY6;yop=00.00.ACF3B0B0.0000.700E Call-ID: FA1DDBAFFDB6F520E74B1197@0e70ffffffff From: "+37060960355" ;tag=0_iX9hYVV00AYhY5 To: ;tag=29e0efc9-df1d-4fe8-b7f5-7d720cfd9e86 CSeq: 2 PRACK Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : tsx0x7f98b401b .......State changed from Trying to Completed, event=TX_MSG [Nov 3 07:48:17] DEBUG[78496]: pjproject:0 : dlg0x7f98b4028 ........Transaction tsx0x7f98b401bd58 state changed to Completed [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000003)' [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TX_MSG [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2453 handle_outgoing: Sending response [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2441 handle_outgoing_response: Method is PRACK, Response is 200 OK [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2345 __print_debug_details: The state change pertains to the endpoint 't2-ossnet-2(PJSIP/t2-ossnet-2-00000003)' [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2350 __print_debug_details: The inv session still has an invite_tsx (0x7f98b4024bc8) [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b401bd58 [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Completed [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is RX_MSG [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is EARLY [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2410 handle_incoming: Received request [Nov 3 07:48:17] DEBUG[78496]: res_pjsip_session.c:2377 handle_incoming_request: Method is PRACK [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : endpoint Request msg OPTIONS/cseq=60383 (tdta0x7f98b4036f00) created. [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3419 endpt_send_request: 0x7f98b4030118: Wrapper created [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3436 endpt_send_request: 0x7f98b4030118: Set timer to 3000 msec [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 .Transaction created for Request msg OPTIONS/cseq=60383 (tdta0x7f98b4036f00) [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 Sending Request msg OPTIONS/cseq=60383 (tdta0x7f98b4036f00) in state Null [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : sip_resolve.c .Target '213.102.45.36:5060' type=UDP resolved to '213.102.45.36:5060' type=UDP (UDP transport) [Nov 3 07:48:18] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:48:18] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:18] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:18] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:18] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP request (424 bytes) to UDP:213.102.45.36:5060 ---> OPTIONS sip:213.102.45.36:5060 SIP/2.0 Via: SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj2235c102-da54-4125-85f0-ef01c056f58d From: ;tag=20aacdeb-29a6-4602-8032-62f3a708a8c9 To: Contact: Call-ID: 9fef9e44-e7d6-4108-ac03-4c8c22e97c36 CSeq: 60383 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 .State changed from Null to Calling, event=TX_MSG [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=60383 (rdata0x7f9834000928) <--- Received SIP response (306 bytes) from UDP:213.102.45.36:5060 ---> SIP/2.0 200 OK Content-Length:0 From:;tag=20aacdeb-29a6-4602-8032-62f3a708a8c9 To:;tag=dummy Via:SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj2235c102-da54-4125-85f0-ef01c056f58d Call-ID:9fef9e44-e7d6-4108-ac03-4c8c22e97c36 CSeq:60383 OPTIONS [Nov 3 07:48:18] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:18] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:48:18] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:18] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:18] DEBUG[78495]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=60383 (rdata0x7f9834000928). Using request transaction as basis [Nov 3 07:48:18] DEBUG[78495]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-0000000a on transaction tsx0x7f98b40233a8 [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=60383 (rdata0x7f9834009e68) [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 .Incoming Response msg 200/OPTIONS/cseq=60383 (rdata0x7f9834009e68) in state Calling [Nov 3 07:48:18] DEBUG[78496]: pjproject:0 : tsx0x7f98b4023 ..State changed from Calling to Completed, event=RX_MSG [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3308 endpt_send_request_cb: 0x7f98b4030118: PJSIP tsx response received [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3321 endpt_send_request_cb: 0x7f98b4030118: Cancelling timer [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3331 endpt_send_request_cb: 0x7f98b4030118: Timer cancelled [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:48:18] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3350 endpt_send_request_cb: 0x7f98b4030118: Callbacks executed [Nov 3 07:48:18] DEBUG[78496]: res_pjsip.c:3401 send_request_wrapper_destructor: 0x7f98b4030118: wrapper destroyed [Nov 3 07:48:18] DEBUG[78501]: res_pjsip/pjsip_configuration.c:284 persistent_endpoint_contact_status_observer: Contact t2-ossnet-2/sip:213.102.45.36:5060 status didn't change: Reachable, RTT: 0.890 msec [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Timeout timer event [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c .State changed from Completed to Terminated, event=TIMER [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : dlg0x7f98b400b ..Transaction tsx0x7f98b403cc48 state changed to Terminated [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2343 __print_debug_details: inv_session 0x7f98b4031988 has no ast session [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS PRACK transaction involved in this state change is 0x7f98b403cc48 [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:48:18] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Timeout timer event [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tdta0x7f983400 ..Destroying txdata Response msg 200/PRACK/cseq=2 (tdta0x7f9834008e30) [Nov 3 07:48:18] DEBUG[78495]: pjproject:0 : tsx0x7f98b403c Transaction destroyed! [Nov 3 07:48:18] DEBUG[78532]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1478159298 Interval: 30 [Nov 3 07:48:18] DEBUG[78532]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Request msg CANCEL/cseq=1 (rdata0x7f9834000928) <--- Received SIP request (552 bytes) from UDP:213.102.45.36:5060 ---> CANCEL sip:963667366321@media.smartmex.lt;user=phone SIP/2.0 Content-Length:0 From:"+37060960355" ;tag=0_iX9hYVV00AYhY5 To: Via:SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;branch=z9hG4bKa_.D22ZYAjgaeh26;yop=00.00.ACF3B0B0.0000.700E Call-ID:FA1DDBAFFDB6F520E74B1197@0e70ffffffff CSeq:1 CANCEL Max-Forwards:70 Route: Request-Disposition:no-fork Reason:X.int ;reasoncode=0x0000030B;add-info=0132.0001.0B2E [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:23] DEBUG[78495]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg CANCEL/cseq=1 (rdata0x7f9834000928) [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : endpoint .Response msg 481/CANCEL/cseq=1 (tdta0x7f9834008e30) created [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : sip_resolve.c .Target '213.102.45.36:5060' type=UDP resolved to '213.102.45.36:5060' type=UDP (UDP transport) [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.45.36:5060' into... [Nov 3 07:48:23] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.45.36' and port '5060'. <--- Transmitting SIP response (463 bytes) to UDP:213.102.45.36:5060 ---> SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/UDP LTMSS2-SIP.TELE2.NET:5060;received=213.102.45.36;branch=z9hG4bKa_.D22ZYAjgaeh26;yop=00.00.ACF3B0B0.0000.700E Call-ID: FA1DDBAFFDB6F520E74B1197@0e70ffffffff From: "+37060960355" ;tag=0_iX9hYVV00AYhY5 To: ;tag=z9hG4bKa_.D22ZYAjgaeh26 CSeq: 1 CANCEL Server: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tdta0x7f983400 .Destroying txdata Response msg 481/CANCEL/cseq=1 (tdta0x7f9834008e30) [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Timeout timer event [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 .State changed from Completed to Terminated, event=TIMER [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Timeout timer event [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tdta0x7f98b403 ..Destroying txdata Request msg OPTIONS/cseq=60383 (tdta0x7f98b4036f00) [Nov 3 07:48:23] DEBUG[78495]: pjproject:0 : tsx0x7f98b4023 Transaction destroyed! [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 Timeout timer event [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 .State changed from Completed to Terminated, event=TIMER [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : dlg0x7f98b400b ..Transaction tsx0x7f98b40074b8 state changed to Terminated [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2331 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2343 __print_debug_details: inv_session 0x7f98b4031988 has no ast session [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2353 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2356 __print_debug_details: The UAS CANCEL transaction involved in this state change is 0x7f98b40074b8 [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2360 __print_debug_details: The current transaction state is Terminated [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2362 __print_debug_details: The transaction state change event is TIMER [Nov 3 07:48:30] DEBUG[78495]: res_pjsip_session.c:2367 __print_debug_details: The current inv state is DISCONNCTD [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : dlg0x7f98b400b ...Dialog destroyed [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 Timeout timer event [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 .State changed from Terminated to Destroyed, event=TIMER [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tdta0x7f98b400 ..Destroying txdata Response msg 200/CANCEL/cseq=1 (tdta0x7f98b400a310) [Nov 3 07:48:30] DEBUG[78495]: pjproject:0 : tsx0x7f98b4007 Transaction destroyed! [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : endpoint Request msg OPTIONS/cseq=59654 (tdta0x7f98b400a310) created. [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3419 endpt_send_request: 0x7f98b401e998: Wrapper created [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3436 endpt_send_request: 0x7f98b401e998: Set timer to 3000 msec [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .Transaction created for Request msg OPTIONS/cseq=59654 (tdta0x7f98b400a310) [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 Sending Request msg OPTIONS/cseq=59654 (tdta0x7f98b400a310) in state Null [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : sip_resolve.c .Target '213.102.44.36:5060' type=UDP resolved to '213.102.44.36:5060' type=UDP (UDP transport) [Nov 3 07:48:32] DEBUG[78496]: res_pjsip_multihomed.c:151 multihomed_on_tx_message: Re-wrote Contact URI host/port to 10.40.6.100:5060 [Nov 3 07:48:32] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:32] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:32] DEBUG[78496]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.44.36:5060' into... [Nov 3 07:48:32] DEBUG[78496]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.44.36' and port '5060'. <--- Transmitting SIP request (424 bytes) to UDP:213.102.44.36:5060 ---> OPTIONS sip:213.102.44.36:5060 SIP/2.0 Via: SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj718713dc-e813-4657-8629-714d4068986f From: ;tag=84e880ff-1801-4893-827b-76eba1db4117 To: Contact: Call-ID: 1cd4b538-ddc7-4e63-a1a6-a410bcb987b9 CSeq: 59654 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 13.11.2 Content-Length: 0 [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .State changed from Null to Calling, event=TX_MSG [Nov 3 07:48:32] DEBUG[78495]: pjproject:0 : sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=59654 (rdata0x7f9834000928) <--- Received SIP response (306 bytes) from UDP:213.102.44.36:5060 ---> SIP/2.0 200 OK Content-Length:0 From:;tag=84e880ff-1801-4893-827b-76eba1db4117 To:;tag=dummy Via:SIP/2.0/UDP 10.40.6.100:5060;rport;branch=z9hG4bKPj718713dc-e813-4657-8629-714d4068986f Call-ID:1cd4b538-ddc7-4e63-a1a6-a410bcb987b9 CSeq:59654 OPTIONS [Nov 3 07:48:32] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '213.102.44.36:5060' into... [Nov 3 07:48:32] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '213.102.44.36' and port '5060'. [Nov 3 07:48:32] DEBUG[78495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.40.6.100:5060' into... [Nov 3 07:48:32] DEBUG[78495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.40.6.100' and port '5060'. [Nov 3 07:48:32] DEBUG[78495]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=59654 (rdata0x7f9834000928). Using request transaction as basis [Nov 3 07:48:32] DEBUG[78495]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-0000000b on transaction tsx0x7f98b40074b8 [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=59654 (rdata0x7f9834009e68) [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 .Incoming Response msg 200/OPTIONS/cseq=59654 (rdata0x7f9834009e68) in state Calling [Nov 3 07:48:32] DEBUG[78496]: pjproject:0 : tsx0x7f98b4007 ..State changed from Calling to Completed, event=RX_MSG [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3308 endpt_send_request_cb: 0x7f98b401e998: PJSIP tsx response received [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3321 endpt_send_request_cb: 0x7f98b401e998: Cancelling timer [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3331 endpt_send_request_cb: 0x7f98b401e998: Timer cancelled [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 3 07:48:32] DEBUG[78496]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3350 endpt_send_request_cb: 0x7f98b401e998: Callbacks executed [Nov 3 07:48:32] DEBUG[78496]: res_pjsip.c:3401 send_request_wrapper_destructor: 0x7f98b401e998: wrapper destroyed [Nov 3 07:48:32] DEBUG[78501]: res_pjsip/pjsip_configuration.c:284 persistent_endpoint_contact_status_observer: Contact t2-ossnet-1/sip:213.102.44.36:5060 status didn't change: Reachable, RTT: 0.875 msec [Nov 3 07:48:37] DEBUG[78621]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying. [Nov 3 07:48:37] DEBUG[78471]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 14