vm-tclabr-y*CLI> [Mar 26 10:22:00] DEBUG[11024]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Mar 26 10:22:00] DEBUG[10490]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 11 [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=2 (rdata0x7ffe38000988) <--- Received SIP request (1205 bytes) from UDP:10.25.194.161:5060 ---> INVITE sip:049851310@10.25.154.129:5060;user=phone SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKa3ba.647e8eb2.0 Via: SIP/2.0/UDP 192.168.210.2:50603;branch=z9hG4bK000000000594eb1fc1db726faa97f3592eaaa9284e2a4971 Max-Forwards: 68 From: "36091256 36091256" ;tag=03daa8c0-594eb1f-t-2 To: Call-ID: 5ecc8135-03daa8c0-002ed850@192.168.210.2 CSeq: 2 INVITE Contact: User-Agent: NetCentrex CCS Softswitch/7.16.0 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, INFO, PRACK, UPDATE, NOTIFY Supported: 100rel P-Asserted-Identity: "36091256 36091256" Privacy: none Content-Type: application/sdp Content-Length: 223 KAMnet: kamnet@10.25.194.161 v=0 o=10.245.16.96 20521228 2 IN IP4 10.245.16.96 s=SIP Call c=IN IP4 10.245.16.96 t=0 0 a=sendrecv m=audio 43264 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=2 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username '36091256;cpc=ordinary' [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.194.161' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.194.161' and port ''. [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j5' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j6' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j7' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'KAMnet_CBS' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n8' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'KAMnet_JAF' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n9' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n4' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n5' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n6' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n7' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 10.25.194.161:5060 matches identify 'KAMnet_BK' [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ..Transaction created for Request msg INVITE/cseq=2 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 .Incoming Request msg INVITE/cseq=2 (rdata0x7ffe38006db8) in state Null [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ..State changed from Null to Trying, event=RX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ...Transaction tsx0x7ffe24008508 state changed to Trying [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a .UAS dialog created [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c .YARON!!!!! ATTRIBUTE COUNT = 4 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a .Module mod-invite added as dialog usage, data=0x7ffe2400bfa8 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ..Session count inc to 2 by mod-invite [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe2402a .UAS invite session created for dialog dlg0x7ffe2402a9b8 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a .Module Session Module added as dialog usage, data=(nil) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ..Session count inc to 2 by Session Module [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:263 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.245.16.96' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.245.16.96' and port ''. [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:421 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ffe24006618' [Mar 26 10:22:01] DEBUG[10510]: res_rtp_asterisk.c:2437 ast_rtp_new: Allocated port 10204 for RTP instance '0x7ffe24006618' [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 ICE session created, comp_cnt=2, role is Unknown agent [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.154.129' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.154.129' and port ''. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Candidate 0 added: comp_id=1, type=host, foundation=Ha199a81, addr=10.25.154.129:10204, base=10.25.154.129:10204, prio=0x7effffff (2130706431) [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:430 ast_rtp_instance_new: RTP instance '0x7ffe24006618' is setup and ready to go [Mar 26 10:22:01] DEBUG[10510]: res_rtp_asterisk.c:4680 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ffe24006618' [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.154.129' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.154.129' and port ''. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Candidate 1 added: comp_id=2, type=host, foundation=Ha199a81, addr=10.25.154.129:10205, base=10.25.154.129:10205, prio=0x7efffffe (2130706430) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Destroying ICE session 0x7ffe24026ce8 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stuse0x7ffe240 STUN session 0x7ffe2401d8b8 destroy request, ref_cnt=4 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stuse0x7ffe240 STUN session 0x7ffe24013ab8 destroy request, ref_cnt=3 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : ice_session.c ICE session 0x7ffe24026ce8 destroyed [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stun_session.c STUN session 0x7ffe2401d8b8 destroyed [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stun_session.c STUN session 0x7ffe24013ab8 destroyed [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe2401f978) based on m type on 0x7ffe10e49580 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe2401f978) based on m type on 0x7ffe10e49580 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe2401f9f8) from 0x7ffe10e49580 to 0x7ffe240067e0 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe2402a8e8) from 0x7ffe10e49580 to 0x7ffe240067e0 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:273 handle_incoming_sdp: Media stream 'audio' handled by audio [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : endpoint .Response msg 100/INVITE/cseq=2 (tdta0x7ffe24029140) created [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a .Initial answer Response msg 100/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe2402a .Sending Response msg 100/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ..Sending Response msg 100/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ..Sending Response msg 100/INVITE/cseq=2 (tdta0x7ffe24029140) in state Trying [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_resolve.c ...Target '10.25.194.161:5060' type=UDP resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP response (584 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bKa3ba.647e8eb2.0 Via: SIP/2.0/UDP 192.168.210.2:50603;branch=z9hG4bK000000000594eb1fc1db726faa97f3592eaaa9284e2a4971 Record-Route: Call-ID: 5ecc8135-03daa8c0-002ed850@192.168.210.2 From: "36091256 36091256" ;tag=03daa8c0-594eb1f-t-2 To: CSeq: 2 INVITE Content-Length: 0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ...State changed from Trying to Proceeding, event=TX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ....Transaction tsx0x7ffe24008508 state changed to Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe24008508) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is INCOMING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1995 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe24008508) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24008508 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is INCOMING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1863 handle_incoming_request: Method is INVITE [Mar 26 10:22:01] DEBUG[10490]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Mar 26 10:22:01] DEBUG[10510]: chan_pjsip.c:2135 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/KAMnet_BK-00000002 [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4522 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:3723 ast_str_retrieve_variable: Result of 'CHANNEL' is 'PJSIP/KAMnet_BK-00000002' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4756 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,"/",2) result is 'KAMnet_BK-00000002' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Set' -- Executing [049851310@app-router:1] Set("PJSIP/KAMnet_BK-00000002", "channeln=KAMnet_BK-00000002") in new stack [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4522 ast_str_substitute_variables_full: Evaluating 'channeln' (from 'channeln}' len 8) [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:3723 ast_str_retrieve_variable: Result of 'channeln' is 'KAMnet_BK-00000002' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4756 pbx_substitute_variables_helper_full: Function CUT(channeln,"-",1) result is 'KAMnet_BK' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Set' -- Executing [049851310@app-router:2] Set("PJSIP/KAMnet_BK-00000002", "channelname=KAMnet_BK") in new stack [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:3723 ast_str_retrieve_variable: Result of 'channelname' is 'KAMnet_BK' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Set' -- Executing [049851310@app-router:3] Set("PJSIP/KAMnet_BK-00000002", "__ChannelName=KAMnet_BK") in new stack [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Answer' -- Executing [049851310@app-router:4] Answer("PJSIP/KAMnet_BK-00000002", "") in new stack [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 2 (In use) [Mar 26 10:22:01] DEBUG[10526]: app_queue.c:2374 device_state_cb: Device 'PJSIP/KAMnet_BK' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c .YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c .YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe2402a .SDP negotiation done, status=0 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.245.16.96' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.245.16.96' and port ''. [Mar 26 10:22:01] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe24006618' [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe2401f608) based on m type on 0x7ffe10e48f10 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe2401f608) based on m type on 0x7ffe10e48f10 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe2401b8f8) from 0x7ffe10e48f10 to 0x7ffe240067e0 [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe2401bd58) from 0x7ffe10e48f10 to 0x7ffe240067e0 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c .YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe2402a .Sending Response msg 200/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ..Sending Response msg 200/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ..Sending Response msg 200/INVITE/cseq=2 (tdta0x7ffe24029140) in state Proceeding <--- Transmitting SIP response (1067 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bKa3ba.647e8eb2.0 Via: SIP/2.0/UDP 192.168.210.2:50603;branch=z9hG4bK000000000594eb1fc1db726faa97f3592eaaa9284e2a4971 Record-Route: Call-ID: 5ecc8135-03daa8c0-002ed850@192.168.210.2 From: "36091256 36091256" ;tag=03daa8c0-594eb1f-t-2 To: ;tag=7c0d9194-d3f8-494a-bf1d-f4b3f6bc7939 CSeq: 2 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 228 v=0 o=- 20521228 4 IN IP4 10.25.154.129 s=Asterisk c=IN IP4 10.25.154.129 t=0 0 m=audio 10204 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ...State changed from Proceeding to Completed, event=TX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ....Transaction tsx0x7ffe24008508 state changed to Completed [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe24008508) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONNECTING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1995 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe24008508) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24008508 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONNECTING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=2 (rdata0x7ffe38000988) <--- Received SIP request (615 bytes) from UDP:10.25.194.161:5060 ---> ACK sip:10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKcydzigwkX Via: SIP/2.0/UDP 192.168.210.2:50603;branch=z9hG4bK000000000594eb1f318c5ce606b982fa5729f7ece32e85b8 Max-Forwards: 69 From: "36091256 36091256" ;tag=03daa8c0-594eb1f-t-2 To: ;tag=7c0d9194-d3f8-494a-bf1d-f4b3f6bc7939 Call-ID: 5ecc8135-03daa8c0-002ed850@192.168.210.2 CSeq: 2 ACK User-Agent: NetCentrex CCS Softswitch/7.16.0 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, INFO, PRACK, UPDATE, NOTIFY Content-Length: 0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=2 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a .Received Request msg ACK/cseq=2 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ..Request to terminate transaction [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24008 ...State changed from Completed to Terminated, event=USER [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe2402a ....Transaction tsx0x7ffe24008508 state changed to Terminated [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24008508 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is USER [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONNECTING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received request [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1863 handle_incoming_request: Method is ACK [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : tsx0x7ffe24008 Timeout timer event [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : tsx0x7ffe24008 .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : tdta0x7ffe2402 ..Destroying txdata Response msg 200/INVITE/cseq=2 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : tsx0x7ffe24008 Transaction destroyed! [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:4301 ast_rtp_read: 0x7ffe240176c0 -- Probation learning mode pass with source address 10.245.16.96:43264 [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Wait' -- Executing [049851310@app-router:5] Wait("PJSIP/KAMnet_BK-00000002", "0.1") in new stack [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:3723 ast_str_retrieve_variable: Result of 'channelname' is 'KAMnet_BK' [Mar 26 10:22:01] DEBUG[11041][C-00000001]: pbx.c:4921 pbx_extension_helper: Launching 'Dial' -- Executing [049851310@app-router:6] Dial("PJSIP/KAMnet_BK-00000002", "PJSIP/036264314@KAMnet_BK,45") in new stack [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 UAC dialog created [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 Module Outbound Authentica added as dialog usage, data=0x7ffe2401b4e0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 Module mod-invite added as dialog usage, data=0x7ffe2401c188 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Session count inc to 2 by mod-invite [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 Module mod-100rel added as dialog usage, data=0x7ffe2401c348 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 100rel module attached [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 UAC invite session created for dialog dlg0x7ffe24008508 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Session count inc to 2 by Session Module [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 Module Session Module added as dialog usage, data=(nil) [Mar 26 10:22:01] DEBUG[11041][C-00000001]: channel.c:6368 ast_channel_inherit_variables: Inheriting variable __ChannelName from PJSIP/KAMnet_BK-00000002 to PJSIP/KAMnet_BK-00000003. -- Called PJSIP/036264314@KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:421 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:01] DEBUG[10510]: res_rtp_asterisk.c:2437 ast_rtp_new: Allocated port 17244 for RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 ICE session created, comp_cnt=2, role is Unknown agent [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.154.129' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.154.129' and port ''. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Candidate 0 added: comp_id=1, type=host, foundation=Ha199a81, addr=10.25.154.129:17244, base=10.25.154.129:17244, prio=0x7effffff (2130706431) [Mar 26 10:22:01] DEBUG[10510]: rtp_engine.c:430 ast_rtp_instance_new: RTP instance '0x7ffe2401bdd8' is setup and ready to go [Mar 26 10:22:01] DEBUG[10510]: res_rtp_asterisk.c:4680 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.154.129' into... [Mar 26 10:22:01] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.154.129' and port ''. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Candidate 1 added: comp_id=2, type=host, foundation=Ha199a81, addr=10.25.154.129:17245, base=10.25.154.129:17245, prio=0x7efffffe (2130706430) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : icess0x7ffe240 Destroying ICE session 0x7ffe2400c628 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stuse0x7ffe240 STUN session 0x7ffe2402c618 destroy request, ref_cnt=4 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stuse0x7ffe240 STUN session 0x7ffe240270f8 destroy request, ref_cnt=3 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : ice_session.c ICE session 0x7ffe2400c628 destroyed [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stun_session.c STUN session 0x7ffe2402c618 destroyed [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : stun_session.c STUN session 0x7ffe240270f8 destroyed [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : endpoint Request msg INVITE/cseq=28878 (tdta0x7ffe24029140) created. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sdp.c YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1912 handle_outgoing_request: Method is INVITE [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .Sending Request msg INVITE/cseq=28878 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ..Sending Request msg INVITE/cseq=28878 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...Transaction created for Request msg INVITE/cseq=28877 (tdta0x7ffe24029140) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Sending Request msg INVITE/cseq=28877 (tdta0x7ffe24029140) in state Null [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_resolve.c ...Target '10.25.194.161:5060' type=Unspecified resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP request (928 bytes) to UDP:10.25.194.161:5060 ---> INVITE sip:036264314@10.25.194.161:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.25.154.129:5060;rport;branch=z9hG4bKPja3ad6f5c-9d4a-47ad-9cd7-e26b560563ed From: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To: Contact: Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c CSeq: 28877 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 237 v=0 o=- 798633591 798633591 IN IP4 10.25.154.129 s=Asterisk c=IN IP4 10.25.154.129 t=0 0 m=audio 17244 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Null to Calling, event=TX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Calling [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CALLING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1995 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending request [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1912 handle_outgoing_request: Method is INVITE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Calling [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CALLING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending request [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1912 handle_outgoing_request: Method is INVITE [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=28877 (rdata0x7ffe38000988) <--- Received SIP response (438 bytes) from UDP:10.25.194.161:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 10.25.154.129:5060;rport=5060;branch=z9hG4bKPja3ad6f5c-9d4a-47ad-9cd7-e26b560563ed From: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To: Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c CSeq: 28877 INVITE Server: kamailio (3.3.1 (x86_64/linux)) Content-Length: 0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .Incoming Response msg 100/INVITE/cseq=28877 (rdata0x7ffe38006db8) in state Calling [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..State changed from Calling to Proceeding, event=RX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Received Response msg 100/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Transaction tsx0x7ffe2402edf8 state changed to Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CALLING [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 100 trying -- your call is important to us [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=28877 (rdata0x7ffe38000988) <--- Received SIP response (759 bytes) from UDP:10.25.194.161:5060 ---> SIP/2.0 180 Ringing Via:SIP/2.0/UDP 10.25.154.129:5060;branch=z9hG4bKPja3ad6f5c-9d4a-47ad-9cd7-e26b560563ed;rport=5060 From:"36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To:;tag=653211588-1427358121614 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:28877 INVITE Contact: Record-Route: RSeq:714489671 P-Asserted-Identity:"Yaniv Simhi" Privacy:none Require:100rel Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Content-Length:0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .Incoming Response msg 180/INVITE/cseq=28877 (rdata0x7ffe38006db8) in state Proceeding [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..State changed from Proceeding to Proceeding, event=RX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Received Response msg 180/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Route-set updated [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Transaction tsx0x7ffe2402edf8 state changed to Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is EARLY [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1995 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 180 Ringing [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : endpoint ....Request msg PRACK/cseq=28879 (tdta0x7ffe24003de0) created. [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .....Sending Request msg PRACK/cseq=28879 (tdta0x7ffe24003de0) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24011 ......Transaction created for Request msg PRACK/cseq=28878 (tdta0x7ffe24003de0) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24011 .....Sending Request msg PRACK/cseq=28878 (tdta0x7ffe24003de0) in state Null [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_resolve.c ......Target '10.25.194.161:0' type=Unspecified resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP request (580 bytes) to UDP:10.25.194.161:5060 ---> PRACK sip:10.25.148.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.154.129:5060;rport;branch=z9hG4bKPje4e40dba-3690-4033-b929-7ebd4723218b From: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To: ;tag=653211588-1427358121614 Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c CSeq: 28878 PRACK Route: RAck: 714489671 28877 INVITE Content-Length: 0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24011 ......State changed from Null to Calling, event=TX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .......Transaction tsx0x7ffe24011b78 state changed to Calling [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24011b78 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Calling [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is EARLY [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending request [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1912 handle_outgoing_request: Method is PRACK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Proceeding [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is EARLY [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 180 Ringing [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK -- PJSIP/KAMnet_BK-00000003 is ringing [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 7 (Ring+Inuse) [Mar 26 10:22:01] DEBUG[11041][C-00000001]: channel.c:4623 ast_indicate_data: Driver for channel 'PJSIP/KAMnet_BK-00000002' does not support indication 3, emulating it [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK [Mar 26 10:22:01] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 7 (Ring+Inuse) [Mar 26 10:22:01] DEBUG[11041][C-00000001]: channel.c:5405 set_format: Set channel PJSIP/KAMnet_BK-00000002 to write format slin [Mar 26 10:22:01] DEBUG[11041][C-00000001]: channel.c:3419 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Mar 26 10:22:01] DEBUG[10526]: app_queue.c:2374 device_state_cb: Device 'PJSIP/KAMnet_BK' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3385 ast_rtp_write: Ooh, format changed from none to alaw [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/PRACK/cseq=28878 (rdata0x7ffe38000988) <--- Received SIP response (382 bytes) from UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via:SIP/2.0/UDP 10.25.154.129:5060;branch=z9hG4bKPje4e40dba-3690-4033-b929-7ebd4723218b;rport=5060 From:"36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To:;tag=653211588-1427358121614 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:28878 PRACK Content-Length:0 [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/PRACK/cseq=28878 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24011 .Incoming Response msg 200/PRACK/cseq=28878 (rdata0x7ffe38006db8) in state Calling [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : tsx0x7ffe24011 ..State changed from Calling to Completed, event=RX_MSG [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Received Response msg 200/PRACK/cseq=28878 (rdata0x7ffe38006db8) [Mar 26 10:22:01] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Transaction tsx0x7ffe24011b78 state changed to Completed [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24011b78 [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is EARLY [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:01] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 200 OK [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:01] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=10 (rdata0x7ffe38000988) <--- Received SIP request (381 bytes) from UDP:10.25.153.149:5060 ---> OPTIONS sip:10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.153.149:5060;branch=z9hG4bK8fe2.815df0a0000000000000000000000000.0 To: From: ;tag=09d14155c60b2ee636f33404fc6b7ec1-df80 CSeq: 10 OPTIONS Call-ID: 13823cf5598bf805-4211@10.25.153.149 Max-Forwards: 70 Content-Length: 0 User-Agent: kamailio (4.2.3 (x86_64/linux)) [Mar 26 10:22:02] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=10 (rdata0x7ffe38006db8) [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username 'KAMnet' [Mar 26 10:22:02] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.153.149' into... [Mar 26 10:22:02] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.153.149' and port ''. [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j5' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j6' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j7' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'KAMnet_CBS' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n8' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'KAMnet_JAF' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n9' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n4' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n5' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n6' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n7' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'KAMnet_BK' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n0' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n1' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n2' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_n3' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'KAMnet_TST' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j8' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j9' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.149:5060 does not match identify 'clacli_j0' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 10.25.153.149:5060 matches identify 'KAMnet_DEV' [Mar 26 10:22:02] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint KAMnet_DEV [Mar 26 10:22:02] DEBUG[10510]: pjsip:0 : endpoint .Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) created [Mar 26 10:22:02] DEBUG[10510]: pjsip:0 : sip_resolve.c .Target '10.25.153.149:5060' type=UDP resolved to '10.25.153.149:5060' type=UDP (UDP transport) <--- Transmitting SIP response (718 bytes) to UDP:10.25.153.149:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.153.149:5060;received=10.25.153.149;branch=z9hG4bK8fe2.815df0a0000000000000000000000000.0 Call-ID: 13823cf5598bf805-4211@10.25.153.149 From: ;tag=09d14155c60b2ee636f33404fc6b7ec1-df80 To: ;tag=z9hG4bK8fe2.815df0a0000000000000000000000000.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Content-Length: 0 [Mar 26 10:22:02] DEBUG[10510]: pjsip:0 : tdta0x7ffe2400 .Destroying txdata Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:02] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:03] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:04] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3956 ast_rtcp_read: Got RTCP report of 168 bytes [Mar 26 10:22:05] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:05] DEBUG[11041][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:05] DEBUG[11041][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:05] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:05] DEBUG[11041][C-00000001]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:4124 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 10.245.16.96:43265 [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:05] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame vm-tclabr-y*CLI> [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:06] DEBUG[10521]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:06] DEBUG[10521]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:06] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:06] DEBUG[10521]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tsx0x7ffe24011 Timeout timer event [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tsx0x7ffe24011 .State changed from Completed to Terminated, event=TIMER [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : dlg0x7ffe24008 ..Transaction tsx0x7ffe24011b78 state changed to Terminated [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24011b78 [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TIMER [Mar 26 10:22:06] DEBUG[10515]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is EARLY [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tsx0x7ffe24011 Timeout timer event [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tsx0x7ffe24011 .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tdta0x7ffe2400 ..Destroying txdata Request msg PRACK/cseq=28878 (tdta0x7ffe24003de0) [Mar 26 10:22:06] DEBUG[10515]: pjsip:0 : tsx0x7ffe24011 Transaction destroyed! [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:06] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:07] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38000988) <--- Received SIP response (1058 bytes) from UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via:SIP/2.0/UDP 10.25.154.129:5060;branch=z9hG4bKPja3ad6f5c-9d4a-47ad-9cd7-e26b560563ed;rport=5060 From:"36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To:;tag=653211588-1427358121614 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:28877 INVITE Contact: Record-Route: P-Asserted-Identity:"Yaniv Simhi" Privacy:none Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Content-Type:application/sdp Content-Length:209 v=0 o=BroadWorks 266946618 1 IN IP4 10.9.9.161 s=- c=IN IP4 10.9.9.161 t=0 0 m=audio 40724 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .Incoming Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38006db8) in state Proceeding [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..State changed from Proceeding to Terminated, event=RX_MSG [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Received Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Route-set updated [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Route-set frozen [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ...Transaction tsx0x7ffe2402edf8 state changed to Terminated [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONNECTING [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1995 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 200 OK [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ....Got SDP answer in Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38006db8) [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : sdp.c ....YARON!!!!! ATTRIBUTE COUNT = 5 [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ....SDP negotiation done, status=0 [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:07] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.9.9.161' into... [Mar 26 10:22:07] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.9.9.161' and port ''. [Mar 26 10:22:07] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:07] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe24009558) based on m type on 0x7ffe10e48bd0 [Mar 26 10:22:07] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe24009558) based on m type on 0x7ffe10e48bd0 [Mar 26 10:22:07] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe2403bee8) from 0x7ffe10e48bd0 to 0x7ffe2401bfa0 [Mar 26 10:22:07] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24032488) from 0x7ffe10e48bd0 to 0x7ffe2401bfa0 [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ....Received Response msg 200/INVITE/cseq=28877 (rdata0x7ffe38006db8), sending ACK [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : endpoint ....Request msg ACK/cseq=28877 (tdta0x7ffe380143c0) created. [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .....Sending Request msg ACK/cseq=28877 (tdta0x7ffe380143c0) [Mar 26 10:22:07] DEBUG[10510]: pjsip:0 : sip_resolve.c .....Target '10.25.194.161:0' type=Unspecified resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP request (546 bytes) to UDP:10.25.194.161:5060 ---> ACK sip:10.25.148.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.154.129:5060;rport;branch=z9hG4bKPj168e6116-5c0e-4a16-831f-0212e8e1ffbe From: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 To: ;tag=653211588-1427358121614 Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c CSeq: 28877 ACK Route: Content-Length: 0 [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1851 __print_debug_details: There is no transaction involved in this state change [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending request [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1912 handle_outgoing_request: Method is ACK [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received response [Mar 26 10:22:07] DEBUG[10510]: res_pjsip_session.c:1880 handle_incoming_response: Response is 200 OK [Mar 26 10:22:07] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK [Mar 26 10:22:07] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 2 (In use) [Mar 26 10:22:07] DEBUG[10526]: app_queue.c:2374 device_state_cb: Device 'PJSIP/KAMnet_BK' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- PJSIP/KAMnet_BK-00000003 answered PJSIP/KAMnet_BK-00000002 [Mar 26 10:22:07] DEBUG[11041][C-00000001]: channel.c:5405 set_format: Set channel PJSIP/KAMnet_BK-00000002 to write format alaw [Mar 26 10:22:07] DEBUG[11041][C-00000001]: channel.c:3419 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 26 10:22:07] DEBUG[11041][C-00000001]: features.c:436 clear_dialed_interfaces: Removing dialed interfaces datastore on PJSIP/KAMnet_BK-00000003 since we're bridging [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge_native_rtp.c:320 native_rtp_bridge_compatible: Bridge '3e583685-0e4c-4468-9478-c0d2ba15bc47' can not use native RTP bridge as two channels are required [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:496 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:491 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:505 find_best_technology: Chose bridge technology simple_bridge [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:784 bridge_base_init: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling simple_bridge technology constructor [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:792 bridge_base_init: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling simple_bridge technology start [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge_channel.c:2510 bridge_channel_internal_join: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007de8(PJSIP/KAMnet_BK-00000002) is joining [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge_channel.c:2510 bridge_channel_internal_join: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) is joining [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge_channel.c:1984 bridge_channel_internal_push: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: pushing 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) -- Channel PJSIP/KAMnet_BK-00000003 joined 'simple_bridge' basic-bridge <3e583685-0e4c-4468-9478-c0d2ba15bc47> [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge_native_rtp.c:320 native_rtp_bridge_compatible: Bridge '3e583685-0e4c-4468-9478-c0d2ba15bc47' can not use native RTP bridge as two channels are required [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:496 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:505 find_best_technology: Chose bridge technology simple_bridge [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:1104 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is already using the new technology. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:996 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000003 already has read format alaw [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:1022 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000003 already has write format alaw [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:424 bridge_channel_complete_join: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) is joining simple_bridge technology [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge_channel.c:1984 bridge_channel_internal_push: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: pushing 0x7ffe40007de8(PJSIP/KAMnet_BK-00000002) -- Channel PJSIP/KAMnet_BK-00000002 joined 'simple_bridge' basic-bridge <3e583685-0e4c-4468-9478-c0d2ba15bc47> [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:505 find_best_technology: Chose bridge technology native_rtp [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1153 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling native_rtp technology constructor [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1171 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: moving 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) to dummy bridge temporarily [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1188 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) is leaving simple_bridge technology (dummy) [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1205 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling simple_bridge technology stop [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:996 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000002 already has read format alaw [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1022 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000002 already has write format alaw [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:424 bridge_channel_complete_join: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007de8(PJSIP/KAMnet_BK-00000002) is joining native_rtp technology [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:996 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000003 already has read format alaw [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1022 bridge_make_compatible: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is happy that channel PJSIP/KAMnet_BK-00000003 already has write format alaw [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:424 bridge_channel_complete_join: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: 0x7ffe40007388(PJSIP/KAMnet_BK-00000003) is joining native_rtp technology [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1216 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling native_rtp technology start [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1233 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47: calling simple_bridge technology destructor [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:505 find_best_technology: Chose bridge technology native_rtp [Mar 26 10:22:07] DEBUG[11041][C-00000001]: bridge.c:1104 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is already using the new technology. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:505 find_best_technology: Chose bridge technology native_rtp [Mar 26 10:22:07] DEBUG[11050][C-00000001]: bridge.c:1104 smart_bridge_operation: Bridge 3e583685-0e4c-4468-9478-c0d2ba15bc47 is already using the new technology. [Mar 26 10:22:07] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Timeout timer event [Mar 26 10:22:07] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:07] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Transaction destroyed! [Mar 26 10:22:07] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:4301 ast_rtp_read: 0x7ffe24021be0 -- Probation learning mode pass with source address 10.9.9.161:40724 [Mar 26 10:22:10] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3956 ast_rtcp_read: Got RTCP report of 168 bytes [Mar 26 10:22:10] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:10] DEBUG[11041][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:10] DEBUG[11041][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:10] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:10] DEBUG[11041][C-00000001]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:10] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:4124 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 10.245.16.96:43265 [Mar 26 10:22:11] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:11] DEBUG[10521]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:11] DEBUG[10521]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:11] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:11] DEBUG[10521]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:11] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=10 (rdata0x7ffe38000988) <--- Received SIP request (340 bytes) from UDP:10.25.194.129:5060 ---> OPTIONS sip:10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.129:5060;branch=z9hG4bK408e.b067ef74.0 To: From: ;tag=c7279b07654bd49dd5dc3b043ca1a7ac-3338 CSeq: 10 OPTIONS Call-ID: 318c347b34b4b118-29986@10.25.194.129 Content-Length: 0 User-Agent: kamailio (3.3.1 (x86_64/linux)) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=10 (rdata0x7ffe38006db8) [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username 'KAMnet' [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.194.129' into... [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.194.129' and port ''. [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.129:5060 does not match identify 'clacli_j5' [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.129:5060 does not match identify 'clacli_j6' [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.129:5060 does not match identify 'clacli_j7' [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 10.25.194.129:5060 matches identify 'KAMnet_CBS' [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint KAMnet_CBS [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : endpoint .Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) created [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sip_resolve.c .Target '10.25.194.129:5060' type=UDP resolved to '10.25.194.129:5060' type=UDP (UDP transport) <--- Transmitting SIP response (671 bytes) to UDP:10.25.194.129:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.129:5060;received=10.25.194.129;branch=z9hG4bK408e.b067ef74.0 Call-ID: 318c347b34b4b118-29986@10.25.194.129 From: ;tag=c7279b07654bd49dd5dc3b043ca1a7ac-3338 To: ;tag=z9hG4bK408e.b067ef74.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Content-Length: 0 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tdta0x7ffe2400 .Destroying txdata Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) [Mar 26 10:22:11] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=714489606 (rdata0x7ffe38000988) <--- Received SIP request (1003 bytes) from UDP:10.25.194.161:5060 ---> INVITE sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKef6d.e663bdd2.0 Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489606-653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489606 INVITE Contact: Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Max-Forwards:20 Content-Type:application/sdp Content-Length:230 v=0 o=BroadWorks 266946618 2 IN IP4 10.9.9.161 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 40724 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=inactive [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg INVITE/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...Transaction created for Request msg INVITE/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Incoming Request msg INVITE/cseq=714489606 (rdata0x7ffe38006db8) in state Null [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Null to Trying, event=RX_MSG [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Trying [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .....Got SDP offer in Request msg INVITE/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:236 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0' into... [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port ''. [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe24009558) based on m type on 0x7ffe10e49030 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 (0x7ffe24009558) based on m type on 0x7ffe10e49030 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe24009558) based on m type on 0x7ffe10e49030 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ffe24028048) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe240104b8) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24024b08) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:245 handle_incoming_sdp: Media stream 'audio' handled by audio [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : endpoint .....Response msg 200/INVITE/cseq=714489606 (tdta0x7ffe24004df0) created [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .....SDP negotiation done, status=0 [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0' into... [Mar 26 10:22:11] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port ''. [Mar 26 10:22:11] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe24009558) based on m type on 0x7ffe10e48a90 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe24009558) based on m type on 0x7ffe10e48a90 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe24036988) from 0x7ffe10e48a90 to 0x7ffe2401bfa0 [Mar 26 10:22:11] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24036de8) from 0x7ffe10e48a90 to 0x7ffe2401bfa0 [Mar 26 10:22:11] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ......Sending Response msg 200/INVITE/cseq=714489606 (tdta0x7ffe24004df0) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .......Sending Response msg 200/INVITE/cseq=714489606 (tdta0x7ffe24004df0) [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .......Sending Response msg 200/INVITE/cseq=714489606 (tdta0x7ffe24004df0) in state Trying [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : sip_resolve.c ........Target '10.25.194.161:5060' type=UDP resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP response (992 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bKef6d.e663bdd2.0 Via: SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489606-653211588-1427358121614 Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c From: ;tag=653211588-1427358121614 To: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 CSeq: 714489606 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 237 v=0 o=- 798633591 798633592 IN IP4 10.25.154.129 s=Asterisk c=IN IP4 10.25.154.129 t=0 0 m=audio 17244 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=inactive [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ........State changed from Trying to Completed, event=TX_MSG [Mar 26 10:22:11] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .........Transaction tsx0x7ffe2402edf8 state changed to Completed [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received request [Mar 26 10:22:11] DEBUG[10510]: res_pjsip_session.c:1863 handle_incoming_request: Method is INVITE [Mar 26 10:22:11] DEBUG[11041][C-00000001]: bridge_native_rtp.c:254 native_rtp_bridge_stop: Discontinued RTP bridging of 'PJSIP/KAMnet_BK-00000002' and 'PJSIP/KAMnet_BK-00000003' - media will flow through Asterisk core [Mar 26 10:22:11] DEBUG[10526]: app_queue.c:2374 device_state_cb: Device 'PJSIP/KAMnet_BK' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. -- Music class default requested but no musiconhold loaded. [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe24024 Timeout timer event [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe24024 .State changed from Completed to Terminated, event=TIMER [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : dlg0x7ffe24006 ..Transaction tsx0x7ffe24024c08 state changed to Terminated [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1836 __print_debug_details: inv_session 0x7ffe24009cc8 has no ast session [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe24024c08 [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TIMER [Mar 26 10:22:12] DEBUG[10515]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is DISCONNCTD [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : dlg0x7ffe24006 ...Dialog destroyed [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe24024 Timeout timer event [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe24024 .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tdta0x7ffe2402 ..Destroying txdata Response msg 200/BYE/cseq=3 (tdta0x7ffe24025370) [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe24024 Transaction destroyed! [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=714489606 (rdata0x7ffe38000988) <--- Received SIP request (566 bytes) from UDP:10.25.194.161:5060 ---> ACK sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKcydzigwkX Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489606A653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489606 ACK Contact: Max-Forwards:20 Content-Length:0 [Mar 26 10:22:12] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:12] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg ACK/cseq=714489606 (rdata0x7ffe38006db8) [Mar 26 10:22:12] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Request to terminate transaction [Mar 26 10:22:12] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Completed to Terminated, event=USER [Mar 26 10:22:12] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Terminated [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is USER [Mar 26 10:22:12] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Timeout timer event [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tdta0x7ffe2400 ..Destroying txdata Response msg 200/INVITE/cseq=714489606 (tdta0x7ffe24004df0) [Mar 26 10:22:12] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Transaction destroyed! [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:12] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:13] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3303 ast_rtp_write: No remote address on RTP instance '0x7ffe2401bdd8' so dropping frame [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=714489607 (rdata0x7ffe38000988) <--- Received SIP request (972 bytes) from UDP:10.25.194.161:5060 ---> INVITE sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKff6d.d404ca41.0 Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489607-653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489607 INVITE Contact: Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Max-Forwards:20 Content-Type:application/sdp Content-Length:199 v=0 o=BroadWorks 266950203 1 IN IP4 10.25.148.3 s=- c=IN IP4 10.25.148.3 t=0 0 m=audio 14532 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg INVITE/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...Transaction created for Request msg INVITE/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Incoming Request msg INVITE/cseq=714489607 (rdata0x7ffe38006db8) in state Null [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Null to Trying, event=RX_MSG [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Trying [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .....Got SDP offer in Request msg INVITE/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 4 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:236 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:13] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.148.3' into... [Mar 26 10:22:13] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.148.3' and port ''. [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe240104b8) based on m type on 0x7ffe10e49030 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe240104b8) based on m type on 0x7ffe10e49030 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe240367f8) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24024b08) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:245 handle_incoming_sdp: Media stream 'audio' handled by audio [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : endpoint .....Response msg 200/INVITE/cseq=714489607 (tdta0x7ffe24025370) created [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .....SDP negotiation done, status=0 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:13] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.148.3' into... [Mar 26 10:22:13] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.148.3' and port ''. [Mar 26 10:22:13] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe240104b8) based on m type on 0x7ffe10e48a90 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe240104b8) based on m type on 0x7ffe10e48a90 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe2400aae8) from 0x7ffe10e48a90 to 0x7ffe2401bfa0 [Mar 26 10:22:13] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24038118) from 0x7ffe10e48a90 to 0x7ffe2401bfa0 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ......Sending Response msg 200/INVITE/cseq=714489607 (tdta0x7ffe24025370) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .......Sending Response msg 200/INVITE/cseq=714489607 (tdta0x7ffe24025370) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .......Sending Response msg 200/INVITE/cseq=714489607 (tdta0x7ffe24025370) in state Trying [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sip_resolve.c ........Target '10.25.194.161:5060' type=UDP resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP response (992 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bKff6d.d404ca41.0 Via: SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489607-653211588-1427358121614 Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c From: ;tag=653211588-1427358121614 To: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 CSeq: 714489607 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 237 v=0 o=- 798633591 798633593 IN IP4 10.25.154.129 s=Asterisk c=IN IP4 10.25.154.129 t=0 0 m=audio 17244 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ........State changed from Trying to Completed, event=TX_MSG [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .........Transaction tsx0x7ffe2402edf8 state changed to Completed [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received request [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1863 handle_incoming_request: Method is INVITE [Mar 26 10:22:13] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK [Mar 26 10:22:13] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 2 (In use) [Mar 26 10:22:13] DEBUG[10526]: app_queue.c:2374 device_state_cb: Device 'PJSIP/KAMnet_BK' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=714489607 (rdata0x7ffe38000988) <--- Received SIP request (566 bytes) from UDP:10.25.194.161:5060 ---> ACK sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKcydzigwkX Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489607A653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489607 ACK Contact: Max-Forwards:20 Content-Length:0 [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg ACK/cseq=714489607 (rdata0x7ffe38006db8) [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Request to terminate transaction [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Completed to Terminated, event=USER [Mar 26 10:22:13] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Terminated [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is USER [Mar 26 10:22:13] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Timeout timer event [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : tdta0x7ffe2402 ..Destroying txdata Response msg 200/INVITE/cseq=714489607 (tdta0x7ffe24025370) [Mar 26 10:22:13] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Transaction destroyed! [Mar 26 10:22:13] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:4301 ast_rtp_read: 0x7ffe24021be0 -- Probation learning mode pass with source address 10.25.148.3:14532 [Mar 26 10:22:14] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3956 ast_rtcp_read: Got RTCP report of 84 bytes [Mar 26 10:22:14] DEBUG[11050][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:14] DEBUG[11050][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:14] DEBUG[11050][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:14] DEBUG[11050][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:14] DEBUG[11050][C-00000001]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:15] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=10 (rdata0x7ffe38000988) <--- Received SIP request (381 bytes) from UDP:10.25.153.150:5060 ---> OPTIONS sip:10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.153.150:5060;branch=z9hG4bK7f27.3278ac80000000000000000000000000.0 To: From: ;tag=134a725d5ea91cdfd4358454f731c609-0453 CSeq: 10 OPTIONS Call-ID: 74f4a4f93bffdbae-8995@10.25.153.150 Max-Forwards: 70 Content-Length: 0 User-Agent: kamailio (4.2.3 (x86_64/linux)) [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=10 (rdata0x7ffe38006db8) [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username 'KAMnet' [Mar 26 10:22:15] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.153.150' into... [Mar 26 10:22:15] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.153.150' and port ''. [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_j5' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_j6' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_j7' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'KAMnet_CBS' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n8' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'KAMnet_JAF' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n9' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n4' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n5' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n6' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n7' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'KAMnet_BK' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n0' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n1' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n2' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.153.150:5060 does not match identify 'clacli_n3' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 10.25.153.150:5060 matches identify 'KAMnet_TST' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint KAMnet_TST [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : endpoint .Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) created [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : sip_resolve.c .Target '10.25.153.150:5060' type=UDP resolved to '10.25.153.150:5060' type=UDP (UDP transport) <--- Transmitting SIP response (718 bytes) to UDP:10.25.153.150:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.153.150:5060;received=10.25.153.150;branch=z9hG4bK7f27.3278ac80000000000000000000000000.0 Call-ID: 74f4a4f93bffdbae-8995@10.25.153.150 From: ;tag=134a725d5ea91cdfd4358454f731c609-0453 To: ;tag=z9hG4bK7f27.3278ac80000000000000000000000000.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Content-Length: 0 [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : tdta0x7ffe2400 .Destroying txdata Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) [Mar 26 10:22:15] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=10 (rdata0x7ffe38000988) <--- Received SIP request (340 bytes) from UDP:10.25.194.161:5060 ---> OPTIONS sip:10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bK3c07.9f19fd66.0 To: From: ;tag=01b62f01a301b47e5ec51bc79f8ad5c8-aa6a CSeq: 10 OPTIONS Call-ID: 23a07b895b2cba45-14616@10.25.194.161 Content-Length: 0 User-Agent: kamailio (3.3.1 (x86_64/linux)) [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=10 (rdata0x7ffe38006db8) [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username 'KAMnet' [Mar 26 10:22:15] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.194.161' into... [Mar 26 10:22:15] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.194.161' and port ''. [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j5' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j6' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_j7' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'KAMnet_CBS' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n8' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'KAMnet_JAF' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n9' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n4' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n5' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n6' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 10.25.194.161:5060 does not match identify 'clacli_n7' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 10.25.194.161:5060 matches identify 'KAMnet_BK' [Mar 26 10:22:15] DEBUG[10510]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint KAMnet_BK [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : endpoint .Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) created [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : sip_resolve.c .Target '10.25.194.161:5060' type=UDP resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP response (671 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bK3c07.9f19fd66.0 Call-ID: 23a07b895b2cba45-14616@10.25.194.161 From: ;tag=01b62f01a301b47e5ec51bc79f8ad5c8-aa6a To: ;tag=z9hG4bK3c07.9f19fd66.0 CSeq: 10 OPTIONS Accept: application/sdp, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, message/sipfrag;version=2.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Content-Length: 0 [Mar 26 10:22:15] DEBUG[10510]: pjsip:0 : tdta0x7ffe2400 .Destroying txdata Response msg 200/OPTIONS/cseq=10 (tdta0x7ffe24004df0) [Mar 26 10:22:15] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:3956 ast_rtcp_read: Got RTCP report of 168 bytes [Mar 26 10:22:15] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:15] DEBUG[11041][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:15] DEBUG[11041][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:15] DEBUG[11041][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:15] DEBUG[11041][C-00000001]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:15] DEBUG[11041][C-00000001]: res_rtp_asterisk.c:4124 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 10.245.16.96:43265 [Mar 26 10:22:16] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:16] DEBUG[10521]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:16] DEBUG[10521]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:16] DEBUG[10521]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:16] DEBUG[10521]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:16] DEBUG[11050][C-00000001]: res_rtp_asterisk.c:3956 ast_rtcp_read: Got RTCP report of 72 bytes [Mar 26 10:22:16] DEBUG[11050][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:16] DEBUG[11050][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'vm-tclabr-y.bgtehila.com' into... [Mar 26 10:22:16] DEBUG[11050][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'vm-tclabr-y.bgtehila.com' and port ''. [Mar 26 10:22:16] DEBUG[11050][C-00000001]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Mar 26 10:22:16] DEBUG[11050][C-00000001]: acl.c:963 ast_find_ourip: Attached to given IP address [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=714489608 (rdata0x7ffe38000988) <--- Received SIP request (741 bytes) from UDP:10.25.194.161:5060 ---> INVITE sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKd07d.675d1477.0 Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489608-653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489608 INVITE Contact: Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Max-Forwards:20 Content-Length:0 [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg INVITE/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...Transaction created for Request msg INVITE/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Incoming Request msg INVITE/cseq=714489608 (rdata0x7ffe38006db8) in state Null [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Null to Trying, event=RX_MSG [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Trying [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : endpoint .....Response msg 200/INVITE/cseq=714489608 (tdta0x7ffe24004df0) created [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ......Sending Response msg 200/INVITE/cseq=714489608 (tdta0x7ffe24004df0) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .......Sending Response msg 200/INVITE/cseq=714489608 (tdta0x7ffe24004df0) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e .......Sending Response msg 200/INVITE/cseq=714489608 (tdta0x7ffe24004df0) in state Trying [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sip_resolve.c ........Target '10.25.194.161:5060' type=UDP resolved to '10.25.194.161:5060' type=UDP (UDP transport) <--- Transmitting SIP response (992 bytes) to UDP:10.25.194.161:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.25.194.161:5060;received=10.25.194.161;branch=z9hG4bKd07d.675d1477.0 Via: SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489608-653211588-1427358121614 Call-ID: 54e18534-89cf-4812-8a42-5966d7c0469c From: ;tag=653211588-1427358121614 To: "36091256 36091256" ;tag=274aa960-d61e-4e91-8913-4942852f52e9 CSeq: 714489608 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 237 v=0 o=- 798633591 798633593 IN IP4 10.25.154.129 s=Asterisk c=IN IP4 10.25.154.129 t=0 0 m=audio 17244 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ........State changed from Trying to Completed, event=TX_MSG [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .........Transaction tsx0x7ffe2402edf8 state changed to Completed [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is TX_MSG [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1939 handle_outgoing: Sending response [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1927 handle_outgoing_response: Method is INVITE, Response is 200 OK [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1842 __print_debug_details: The inv session still has an invite_tsx (0x7ffe2402edf8) [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Completed [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is RX_MSG [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1896 handle_incoming: Received request [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1863 handle_incoming_request: Method is INVITE [Mar 26 10:22:16] DEBUG[10502]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - KAMnet_BK [Mar 26 10:22:16] DEBUG[10502]: devicestate.c:464 do_state_change: Changing state for PJSIP/KAMnet_BK - state 2 (In use) [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=714489608 (rdata0x7ffe38000988) <--- Received SIP request (797 bytes) from UDP:10.25.194.161:5060 ---> ACK sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKcydzigwkX Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489608A653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489608 ACK Contact: Max-Forwards:20 Content-Type:application/sdp Content-Length:199 v=0 o=BroadWorks 266950203 1 IN IP4 10.25.148.3 s=- c=IN IP4 10.25.148.3 t=0 0 m=audio 14532 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg ACK/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ..Got SDP answer in Request msg ACK/cseq=714489608 (rdata0x7ffe38006db8) [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : sdp.c ..YARON!!!!! ATTRIBUTE COUNT = 4 [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 ..SDP negotiation done, status=0 [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:16] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.148.3' into... [Mar 26 10:22:16] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.148.3' and port ''. [Mar 26 10:22:16] DEBUG[10510]: res_rtp_asterisk.c:4735 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ffe2401bdd8' [Mar 26 10:22:16] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe24032488) based on m type on 0x7ffe10e48d10 [Mar 26 10:22:16] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe24032488) based on m type on 0x7ffe10e48d10 [Mar 26 10:22:16] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe2400b058) from 0x7ffe10e48d10 to 0x7ffe2401bfa0 [Mar 26 10:22:16] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe2400f978) from 0x7ffe10e48d10 to 0x7ffe2401bfa0 [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Request to terminate transaction [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Completed to Terminated, event=USER [Mar 26 10:22:16] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Terminated [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1828 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1839 __print_debug_details: The state change pertains to the session with KAMnet_BK [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1844 __print_debug_details: The inv session does NOT have an invite_tsx [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1847 __print_debug_details: The transaction involved in this state change is 0x7ffe2402edf8 [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1848 __print_debug_details: The current transaction state is Terminated [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1849 __print_debug_details: The transaction state change event is USER [Mar 26 10:22:16] DEBUG[10510]: res_pjsip_session.c:1853 __print_debug_details: The current inv state is CONFIRMED [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Timeout timer event [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e .State changed from Terminated to Destroyed, event=TIMER [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : tdta0x7ffe2400 ..Destroying txdata Response msg 200/INVITE/cseq=714489608 (tdta0x7ffe24004df0) [Mar 26 10:22:16] DEBUG[10515]: pjsip:0 : tsx0x7ffe2402e Transaction destroyed! [Mar 26 10:22:17] DEBUG[10515]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=714489609 (rdata0x7ffe38000988) <--- Received SIP request (976 bytes) from UDP:10.25.194.161:5060 ---> INVITE sip:39ceef9b-77cf-4cf2-8e4d-cb1c3ec45d31@10.25.154.129:5060 SIP/2.0 Via: SIP/2.0/UDP 10.25.194.161:5060;branch=z9hG4bKc07d.9beb0b63.0 Via:SIP/2.0/UDP 10.25.148.1;branch=z9hG4bKBroadWorks.2prrn7-10.25.194.161V5060-0-714489609-653211588-1427358121614 From:;tag=653211588-1427358121614 To:"36091256 36091256";tag=274aa960-d61e-4e91-8913-4942852f52e9 Call-ID:54e18534-89cf-4812-8a42-5966d7c0469c CSeq:714489609 INVITE Contact: Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY,UPDATE Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Max-Forwards:20 Content-Type:application/sdp Content-Length:203 v=0 o=BroadWorks 266951469 1 IN IP4 10.25.147.203 s=- c=IN IP4 10.25.147.203 t=0 0 m=audio 12120 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=714489609 (rdata0x7ffe38006db8) [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 .Received Request msg INVITE/cseq=714489609 (rdata0x7ffe38006db8) [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...Transaction created for Request msg INVITE/cseq=714489609 (rdata0x7ffe38006db8) [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ..Incoming Request msg INVITE/cseq=714489609 (rdata0x7ffe38006db8) in state Null [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : tsx0x7ffe2402e ...State changed from Null to Trying, event=RX_MSG [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : dlg0x7ffe24008 ....Transaction tsx0x7ffe2402edf8 state changed to Trying [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : inv0x7ffe24008 .....Got SDP offer in Request msg INVITE/cseq=714489609 (rdata0x7ffe38006db8) [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 4 [Mar 26 10:22:17] DEBUG[10510]: res_pjsip_session.c:236 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Mar 26 10:22:17] DEBUG[10510]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.25.147.203' into... [Mar 26 10:22:17] DEBUG[10510]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.25.147.203' and port ''. [Mar 26 10:22:17] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ffe24032488) based on m type on 0x7ffe10e49030 [Mar 26 10:22:17] DEBUG[10510]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ffe24032488) based on m type on 0x7ffe10e49030 [Mar 26 10:22:17] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ffe24008058) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:17] DEBUG[10510]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ffe24024b08) from 0x7ffe10e49030 to 0x7ffe2401bfa0 [Mar 26 10:22:17] DEBUG[10510]: res_pjsip_session.c:245 handle_incoming_sdp: Media stream 'audio' handled by audio [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 [Mar 26 10:22:17] DEBUG[10510]: pjsip:0 : sdp.c .....YARON!!!!! ATTRIBUTE COUNT = 6 vm-tclabr-y*CLI> Disconnected from Asterisk server Asterisk cleanly ending (0). Executing last minute cleanups You have new mail in /var/spool/mail/root [root@vm-tclabr-y asterisk]#