-- Called PJSIP/09001234@proxy [Nov 23 12:13:09] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting read format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:3163 rtp_allocate_transport: Allocated port 29352 for RTP instance '0x7f49280154b8' [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:3191 rtp_allocate_transport: Creating ICE session [::]:29352 (29352) for RTP instance '0x7f49280154b8' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc02' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc02' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc02' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc02' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.0.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.0.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.0.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.0.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.2.0.1' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.2.0.1' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.2.0.1' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.2.0.1' and port ''. [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:488 ast_rtp_instance_new: RTP instance '0x7f49280154b8' is setup and ready to go [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'everest01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'everest01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6137 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f49280154b8' [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:471 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f4928052948' [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:3163 rtp_allocate_transport: Allocated port 10664 for RTP instance '0x7f4928052948' [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:3191 rtp_allocate_transport: Creating ICE session [::]:10664 (10664) for RTP instance '0x7f4928052948' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc02' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc02' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'fe80::601:d9ff:fefb:cc02' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'fe80::601:d9ff:fefb:cc02' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port ''. [Nov 23 12:13:09] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting write format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting read format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting write format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.0.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.0.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.0.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.0.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.2.0.1' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.2.0.1' and port ''. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.2.0.1' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.2.0.1' and port ''. [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:488 ast_rtp_instance_new: RTP instance '0x7f4928052948' is setup and ready to go [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'everest01' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'everest01' and port ''. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6137 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f4928052948' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3220 handle_outgoing_request: Method is INVITE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'asterisk.dev.com' is 'UDP' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7f4928071b10] Created resolution tracking for target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7f4928071b10] Added target 'asterisk.dev.com' with record type '1', transport 'UDP', and port '8065' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:613 sip_resolve: [0x7f4928071b10] Starting initial resolution using parallel queries for target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CALLING [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3359 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7f4928071b10] All parallel queries completed [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:326 sip_resolve_callback: [0x7f4928071b10] A record received on target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7f4928071b10] Resolution completed - 1 viable targets [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f492806faa8 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Calling [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is TX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CALLING [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:201 sip_resolve_invoke_user_callback: [0x7f4928071b10] Address '0' is 1.6.1.6:8065 with transport 'UDP' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7f4928071b10] Invoking user callback with '1' addresses [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (1080 bytes) to UDP:1.6.1.6:8065 ---> INVITE sip:09001234@asterisk.dev.com:8065 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj58e6b2a6-9c4b-447d-8d7c-8e56caf4e8a0 From: ;tag=3c89434d-10e5-4399-9cdf-e3c08828980e To: Contact: Call-ID: a1e76d22-9125-4566-9ba5-e4450e10f30e CSeq: 2778 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 X-CompanyId: 7442 Max-Forwards: 70 User-Agent: PBX Content-Type: application/sdp Content-Length: 372 v=0 o=- 1758798672 1758798672 IN IP4 1.6.1.6 s=Asterisk c=IN IP4 1.6.1.6 t=0 0 m=audio 29352 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 10664 RTP/AVP 99 a=rtpmap:99 H264/90000 a=sendrecv <--- Received SIP response (366 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj58e6b2a6-9c4b-447d-8d7c-8e56caf4e8a0 From: ;tag=3c89434d-10e5-4399-9cdf-e3c08828980e To: Call-ID: a1e76d22-9125-4566-9ba5-e4450e10f30e CSeq: 2778 INVITE Server: Proxy 1 Content-Length: 0 [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f492800ad68 for Response msg 100/INVITE/cseq=2778 (rdata0x7f4920008d28) [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/proxy-178.62.1-00000058 associated with dialog dlg0x7f492800ad68 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f492806faa8 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Proceeding [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is RX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CALLING [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 100 Trying [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3765 endpt_send_request: 0x7f4928071c88: Wrapper created [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3780 endpt_send_request: 0x7f4928071c88: Set timer to 3000 msec [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'asterisk.dev.com' is 'UDP' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7f492805bb40] Created resolution tracking for target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7f492805bb40] Added target 'asterisk.dev.com' with record type '1', transport 'UDP', and port '8065' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:613 sip_resolve: [0x7f492805bb40] Starting initial resolution using parallel queries for target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7f492805bb40] All parallel queries completed [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:326 sip_resolve_callback: [0x7f492805bb40] A record received on target 'asterisk.dev.com' [Nov 23 12:13:09] DEBUG[28201]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7f492805bb40] Resolution completed - 1 viable targets [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:201 sip_resolve_invoke_user_callback: [0x7f492805bb40] Address '0' is 1.6.1.6:8065 with transport 'UDP' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7f492805bb40] Invoking user callback with '1' addresses [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (475 bytes) to UDP:1.6.1.6:8065 ---> OPTIONS sip:asterisk.dev.com:8065 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj143d7232-0645-4df7-b75a-4246860db4c3 From: ;tag=ee125cc8-145c-4cad-93e8-1e568bfc4295 To: Contact: Call-ID: 540cd23e-092a-42c8-887c-29fa7f840cd5 CSeq: 25636 OPTIONS Max-Forwards: 70 User-Agent: PBX Content-Length: 0 <--- Received SIP response (476 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj143d7232-0645-4df7-b75a-4246860db4c3 From: ;tag=ee125cc8-145c-4cad-93e8-1e568bfc4295 To: ;tag=f6db893b20b9ff3026e3f35c1241bd8c.98cb Call-ID: 540cd23e-092a-42c8-887c-29fa7f840cd5 CSeq: 25636 OPTIONS Accept: */* Accept-Encoding: Accept-Language: en Supported: Server: Proxy 1 Content-Length: 0 [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:519 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=25636 (rdata0x7f4920008d28). Using request transaction as basis. [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:127 find_request_serializer: Found transaction tsx0x7f4928072848 for Response msg 200/OPTIONS/cseq=25636 (rdata0x7f4920008d28). [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:137 find_request_serializer: Found serializer pjsip/default-0000000c on transaction tsx0x7f4928072848 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3643 endpt_send_request_cb: 0x7f4928071c88: PJSIP tsx response received [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3656 endpt_send_request_cb: 0x7f4928071c88: Cancelling timer [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3665 endpt_send_request_cb: 0x7f4928071c88: Timer cancelled [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:09] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3686 endpt_send_request_cb: 0x7f4928071c88: Callbacks executed [Nov 23 12:13:09] DEBUG[28215]: res_pjsip.c:3742 send_request_wrapper_destructor: 0x7f4928071c88: wrapper destroyed [Nov 23 12:13:09] DEBUG[28223]: res_pjsip/pjsip_configuration.c:281 persistent_endpoint_contact_status_observer: Contact proxy/sip:asterisk.dev.com:8065 status didn't change: Reachable, RTT: 12.085 msec <--- Received SIP response (1031 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj58e6b2a6-9c4b-447d-8d7c-8e56caf4e8a0 Record-Route: Record-Route: From: ;tag=3c89434d-10e5-4399-9cdf-e3c08828980e To: ;tag=isixfr1frK4 Call-ID: a1e76d22-9125-4566-9ba5-e4450e10f30e CSeq: 2778 INVITE Server: Mediaserver Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, NOTIFY, SUBSCRIBE Contact: Content-Type: application/sdp Content-Length: 302 Supported: replaces v=0 o=root 1884660962 1884660962 IN IP4 1.1.1.2 s=Mediaserver c=IN IP4 1.1.1.2 t=0 0 m=audio 19140 RTP/AVP 8 0 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 0 RTP/AVP 99 [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f492800ad68 for Response msg 183/INVITE/cseq=2778 (rdata0x7f4920008d28) [Nov 23 12:13:09] DEBUG[28214]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/proxy-178.62.1-00000058 associated with dialog dlg0x7f492800ad68 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is EARLY [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3359 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 183 Session Progress [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f49280154b8' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.2', our source address is '1.6.1.6'. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f49280154b8' > 0x7f4928027e70 -- Strict RTP learning after remote address set to: 1.1.1.2:19140 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f48ecb72d90 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f48ecb72d90 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f48ecb72d90 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f48ecb72d90 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f4928012070) from 0x7f48ecb72d90 to 0x7f4928015680 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 3 (0x7f492805c180) from 0x7f48ecb72d90 to 0x7f4928015680 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7f4928011ff0) from 0x7f48ecb72d90 to 0x7f4928015680 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x23fd990) from 0x7f48ecb72d90 to 0x7f4928015680 [Nov 23 12:13:09] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting read format path: alaw -> g722 [Nov 23 12:13:09] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting write format path: g722 -> alaw [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f4928052948' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port ''. [Nov 23 12:13:09] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.2', our source address is '1.6.1.6'. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f4928052948' > 0x7f4928054440 -- Strict RTP learning after remote address set to: 1.1.1.2:0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f48ecb72d90 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 99 (0x23fd8f0) from 0x7f48ecb72d90 to 0x7f4928052b10 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f492806faa8 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Proceeding [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is RX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is EARLY [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 183 Session Progress -- PJSIP/proxy-00000001 is making progress passing it to PJSIP/proxy-00000000 [Nov 23 12:13:09] DEBUG[28199]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy [Nov 23 12:13:09] DEBUG[28199]: devicestate.c:472 do_state_change: Changing state for PJSIP/proxy - state 2 (In use) [Nov 23 12:13:09] DEBUG[28245]: app_queue.c:2545 device_state_cb: Device 'PJSIP/proxy' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f492800f398' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.9', our source address is '1.6.1.6'. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f492800f398' > 0x7f4928020620 -- Strict RTP learning after remote address set to: 1.1.1.9:5008 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 96 based on m type on 0x7f48ecb72fe0 > 0x7f4928027e70 -- Strict RTP switching to RTP target address 1.1.1.2:19140 as source [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 98 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 102 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 103 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 104 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f49280690b0) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 3 (0x7f49280692b0) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7f4928069100) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 9 (0x7f492806c220) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 96 (0x7f4928073250) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 97 (0x7f492804fdf0) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 98 (0x7f492807f9d0) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 100 (0x7f492807e630) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x23fd990) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 102 (0x7f492807ea90) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 103 (0x7f4928069150) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 104 (0x7f4928069300) from 0x7f48ecb72fe0 to 0x7f492800f560 [Nov 23 12:13:09] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting read format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting write format path: g722 -> g722 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f4928011238' [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.9' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.9' and port ''. [Nov 23 12:13:09] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.9', our source address is '1.6.1.6'. [Nov 23 12:13:09] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f4928011238' > 0x7f4928037d70 -- Strict RTP learning after remote address set to: 1.1.1.9:5010 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 105 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f48ecb72fe0 [Nov 23 12:13:09] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 105 (0x7f492804e800) from 0x7f48ecb72fe0 to 0x7f4928011400 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3235 handle_outgoing_response: Method is INVITE, Response is 183 Session Progress [Nov 23 12:13:09] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:09] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP response (1342 bytes) to UDP:1.6.1.6:8065 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 1.6.1.6:8065;rport=8065;received=1.6.1.6;branch=z9hG4bK5be3.4d42378d68478edd69ae44f093b8724e.0 Via: SIP/2.0/UDP 1.6.1.6:8060;branch=z9hG4bK5be3.1fe0e8eafad7b826a80fda10e5f811dd.0 Via: SIP/2.0/UDP 1.1.1.9:5060;rport=5060;received=4.1.3.1;branch=z9hG4bK-373138-74a8aff9eb199ecdaeee4ca385e30dc9 Record-Route: Record-Route: Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 From: "phone_27407_0" ;tag=e507bbb7 To: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 CSeq: 2 INVITE Server: PBX Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Content-Type: application/sdp Content-Length: 356 v=0 o=- 0 2 IN IP4 1.6.1.6 s=Asterisk c=IN IP4 1.6.1.6 t=0 0 m=audio 38636 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 25680 RTP/AVP 105 a=rtpmap:105 H264/90000 a=sendonly [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f4928017ef8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is EARLY [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3359 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f4928017ef8) [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f4928017ef8 [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Proceeding [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is TX_MSG [Nov 23 12:13:09] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is EARLY [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4283 ast_rtp_write: Ooh, format changed from none to g722 [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4119 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f492800f398' [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5687 ast_rtp_read: 0x7f4928020620 -- Received RTP packet from 4.1.3.1:5008, dropping due to strict RTP protection. Qualifying new stream. [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5678 ast_rtp_read: 0x7f4928020620 -- Received RTP packet from 4.1.3.1:5008, dropping due to strict RTP protection. Will switch to it in 3 packets. [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5678 ast_rtp_read: 0x7f4928020620 -- Received RTP packet from 4.1.3.1:5008, dropping due to strict RTP protection. Will switch to it in 2 packets. [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5678 ast_rtp_read: 0x7f4928020620 -- Received RTP packet from 4.1.3.1:5008, dropping due to strict RTP protection. Will switch to it in 1 packets. > 0x7f4928020620 -- Strict RTP switching source address to 4.1.3.1:5008 [Nov 23 12:13:09] DEBUG[28252][C-00000001]: acl.c:955 ast_ouraddrfor: For destination '4.1.3.1', our source address is '1.6.1.6'. [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f492800f398' [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4283 ast_rtp_write: Ooh, format changed from none to alaw [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32654, expecting 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32655, expecting 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32656, expecting 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32657, expecting 84) [Nov 23 12:13:09] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32658, expecting 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32659, expecting 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32660, expecting 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32661, expecting 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) > 0x7f4928027e70 -- Strict RTP learning complete - Locking on source address 1.1.1.2:19140 > 0x7f4928020620 -- Strict RTP learning complete - Locking on source address 4.1.3.1:5008 [Nov 23 12:13:10] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32662, expecting 84) [Nov 23 12:13:10] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32663, expecting 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32664, expecting 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 124 bytes from 4.1.3.1:5009 [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5009' into... [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5009'. [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:38637' into... [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '38637'. [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32665, expecting 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 80 bytes from 4.1.3.1:5011 [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5011' into... [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5011'. [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:25681' into... [Nov 23 12:13:11] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '25681'. [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32666, expecting 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32667, expecting 84) [Nov 23 12:13:11] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32668, expecting 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32669, expecting 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32670, expecting 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:12] DEBUG[28235]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1511435592 Interval: 30 [Nov 23 12:13:12] DEBUG[28235]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [Nov 23 12:13:12] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32671, expecting 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32672, expecting 84) [Nov 23 12:13:12] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32673, expecting 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32674, expecting 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:5541 ast_rtp_read: Using IPv6 mapped address 4.1.3.1:5008 for STUN [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:287 ast_stun_handle_packet: Scrambled STUN packet length (got 32675, expecting 84) [Nov 23 12:13:13] DEBUG[28252][C-00000001]: stun.c:300 ast_stun_handle_packet: Inconsistent Attribute (length 8228 exceeds remaining msg len 84) [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3765 endpt_send_request: 0x7f492805af38: Wrapper created [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3780 endpt_send_request: 0x7f492805af38: Set timer to 3000 msec [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'proxy.dev.com' [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'proxy.dev.com' is 'UDP' [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7f4928057040] Created resolution tracking for target 'proxy.dev.com' [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7f4928057040] Added target 'proxy.dev.com' with record type '1', transport 'UDP', and port '8065' [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:613 sip_resolve: [0x7f4928057040] Starting initial resolution using parallel queries for target 'proxy.dev.com' [Nov 23 12:13:14] DEBUG[28201]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7f4928057040] All parallel queries completed [Nov 23 12:13:14] DEBUG[28201]: res_pjsip/pjsip_resolver.c:326 sip_resolve_callback: [0x7f4928057040] A record received on target 'proxy.dev.com' [Nov 23 12:13:14] DEBUG[28201]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7f4928057040] Resolution completed - 1 viable targets [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:201 sip_resolve_invoke_user_callback: [0x7f4928057040] Address '0' is 1.1.5.2:8065 with transport 'UDP' [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7f4928057040] Invoking user callback with '1' addresses [Nov 23 12:13:14] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:14] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:14] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:14] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.5.2:8065' into... [Nov 23 12:13:14] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.5.2' and port '8065'. <--- Transmitting SIP request (475 bytes) to UDP:1.1.5.2:8065 ---> OPTIONS sip:proxy.dev.com:8065 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj82ecc107-6c83-465c-9dd1-2fdaa4359794 From: ;tag=b574a6b7-63df-4f74-a6be-2fb29327e51c To: Contact: Call-ID: f1b6b2bc-8d26-44fb-ba07-aebe8e6dc3ab CSeq: 59518 OPTIONS Max-Forwards: 70 User-Agent: PBX Content-Length: 0 <--- Received SIP response (476 bytes) from UDP:1.1.5.2:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj82ecc107-6c83-465c-9dd1-2fdaa4359794 From: ;tag=b574a6b7-63df-4f74-a6be-2fb29327e51c To: ;tag=d4d563dde07c0116b8df5fecd2d4dcf7.9066 Call-ID: f1b6b2bc-8d26-44fb-ba07-aebe8e6dc3ab CSeq: 59518 OPTIONS Accept: */* Accept-Encoding: Accept-Language: en Supported: Server: Proxy 2 Content-Length: 0 [Nov 23 12:13:14] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.5.2:8065' into... [Nov 23 12:13:14] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.5.2' and port '8065'. [Nov 23 12:13:14] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:14] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:14] DEBUG[28214]: res_pjsip/pjsip_distributor.c:519 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=59518 (rdata0x7f4920008d28). Using request transaction as basis. [Nov 23 12:13:14] DEBUG[28214]: res_pjsip/pjsip_distributor.c:127 find_request_serializer: Found transaction tsx0x7f492808c558 for Response msg 200/OPTIONS/cseq=59518 (rdata0x7f4920008d28). [Nov 23 12:13:14] DEBUG[28214]: res_pjsip/pjsip_distributor.c:137 find_request_serializer: Found serializer pjsip/default-0000000d on transaction tsx0x7f492808c558 [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3643 endpt_send_request_cb: 0x7f492805af38: PJSIP tsx response received [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3656 endpt_send_request_cb: 0x7f492805af38: Cancelling timer [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3665 endpt_send_request_cb: 0x7f492805af38: Timer cancelled [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:14] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:14] DEBUG[28223]: res_pjsip/pjsip_configuration.c:281 persistent_endpoint_contact_status_observer: Contact proxy-1.1.5.2/sip:proxy.dev.com:8065 status didn't change: Reachable, RTT: 12.352 msec [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3686 endpt_send_request_cb: 0x7f492805af38: Callbacks executed [Nov 23 12:13:14] DEBUG[28215]: res_pjsip.c:3742 send_request_wrapper_destructor: 0x7f492805af38: wrapper destroyed [Nov 23 12:13:14] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 28 bytes from 4.1.3.1:5011 [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5011' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5011'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:25681' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '25681'. [Nov 23 12:13:14] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 64 bytes from 1.1.1.2:19141 [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2:19141' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port '19141'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:29353' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '29353'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:29353' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '29353'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2:19141' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port '19141'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:38637' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '38637'. [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5009' into... [Nov 23 12:13:14] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5009'. [Nov 23 12:13:18] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 72 bytes from 4.1.3.1:5009 [Nov 23 12:13:18] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5009' into... [Nov 23 12:13:18] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5009'. [Nov 23 12:13:18] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:38637' into... [Nov 23 12:13:18] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '38637'. [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3765 endpt_send_request: 0x7f492802b658: Wrapper created [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3780 endpt_send_request: 0x7f492802b658: Set timer to 3000 msec [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'asterisk.dev.com' [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'asterisk.dev.com' is 'UDP' [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7f492806bf00] Created resolution tracking for target 'asterisk.dev.com' [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7f492806bf00] Added target 'asterisk.dev.com' with record type '1', transport 'UDP', and port '8065' [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:613 sip_resolve: [0x7f492806bf00] Starting initial resolution using parallel queries for target 'asterisk.dev.com' [Nov 23 12:13:19] DEBUG[28201]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7f492806bf00] All parallel queries completed [Nov 23 12:13:19] DEBUG[28201]: res_pjsip/pjsip_resolver.c:326 sip_resolve_callback: [0x7f492806bf00] A record received on target 'asterisk.dev.com' [Nov 23 12:13:19] DEBUG[28201]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7f492806bf00] Resolution completed - 1 viable targets [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:201 sip_resolve_invoke_user_callback: [0x7f492806bf00] Address '0' is 1.6.1.6:8065 with transport 'UDP' [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7f492806bf00] Invoking user callback with '1' addresses [Nov 23 12:13:19] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:19] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:19] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:19] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:19] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (475 bytes) to UDP:1.6.1.6:8065 ---> OPTIONS sip:asterisk.dev.com:8065 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj3c854267-c096-4066-95f5-fc8ef1c32f6d From: ;tag=f88b09fc-8bf0-4806-bcfc-47d862a82894 To: Contact: Call-ID: 44fdfa11-4b34-473d-9e31-f4824230bc1a CSeq: 42981 OPTIONS Max-Forwards: 70 User-Agent: PBX Content-Length: 0 <--- Received SIP response (476 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj3c854267-c096-4066-95f5-fc8ef1c32f6d From: ;tag=f88b09fc-8bf0-4806-bcfc-47d862a82894 To: ;tag=f6db893b20b9ff3026e3f35c1241bd8c.e5c3 Call-ID: 44fdfa11-4b34-473d-9e31-f4824230bc1a CSeq: 42981 OPTIONS Accept: */* Accept-Encoding: Accept-Language: en Supported: Server: Proxy 1 Content-Length: 0 [Nov 23 12:13:19] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:19] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:19] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:19] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:19] DEBUG[28214]: res_pjsip/pjsip_distributor.c:519 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=42981 (rdata0x7f4920008d28). Using request transaction as basis. [Nov 23 12:13:19] DEBUG[28214]: res_pjsip/pjsip_distributor.c:127 find_request_serializer: Found transaction tsx0x7f492808c558 for Response msg 200/OPTIONS/cseq=42981 (rdata0x7f4920008d28). [Nov 23 12:13:19] DEBUG[28214]: res_pjsip/pjsip_distributor.c:137 find_request_serializer: Found serializer pjsip/default-0000000e on transaction tsx0x7f492808c558 [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3643 endpt_send_request_cb: 0x7f492802b658: PJSIP tsx response received [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3656 endpt_send_request_cb: 0x7f492802b658: Cancelling timer [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3665 endpt_send_request_cb: 0x7f492802b658: Timer cancelled [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:19] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3686 endpt_send_request_cb: 0x7f492802b658: Callbacks executed [Nov 23 12:13:19] DEBUG[28215]: res_pjsip.c:3742 send_request_wrapper_destructor: 0x7f492802b658: wrapper destroyed [Nov 23 12:13:19] DEBUG[28223]: res_pjsip/pjsip_configuration.c:281 persistent_endpoint_contact_status_observer: Contact proxy/sip:asterisk.dev.com:8065 status didn't change: Reachable, RTT: 4.218 msec [Nov 23 12:13:19] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 64 bytes from 1.1.1.2:19141 [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2:19141' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port '19141'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:29353' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '29353'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:29353' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '29353'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2:19141' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port '19141'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:38637' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '38637'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5009' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5009'. [Nov 23 12:13:19] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 28 bytes from 4.1.3.1:5011 [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5011' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5011'. [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:25681' into... [Nov 23 12:13:19] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '25681'. <--- Received SIP response (1061 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj58e6b2a6-9c4b-447d-8d7c-8e56caf4e8a0 Record-Route: Record-Route: From: ;tag=3c89434d-10e5-4399-9cdf-e3c08828980e To: ;tag=as45d5af4f Call-ID: a1e76d22-9125-4566-9ba5-e4450e10f30e CSeq: 2778 INVITE User-Agent: SBC Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 287 v=0 o=root 4067 4067 IN IP4 8.2.1.8 s=session c=IN IP4 8.2.1.8 t=0 0 m=audio 12796 RTP/AVP 8 0 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv [Nov 23 12:13:20] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:20] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:20] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:20] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. !!! [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f492800ad68 for Response msg 200/INVITE/cseq=2778 (rdata0x7f4920008d28) [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/proxy-178.62.1-00000058 associated with dialog dlg0x7f492800ad68 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONNECTING [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3359 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 200 OK [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:798 handle_negotiated_sdp: Pending topology was NULL for channel 'PJSIP/proxy-00000001' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '1.6.1.6' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '1.6.1.6' is 'UDP' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '1.6.1.6' is an IP address, skipping resolution [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (634 bytes) to UDP:1.6.1.6:8065 ---> ACK sip:31887732500@8.2.1.8 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj16aca549-66d1-44c8-8444-01a56d0efc70 From: ;tag=3c89434d-10e5-4399-9cdf-e3c08828980e To: ;tag=as45d5af4f Call-ID: a1e76d22-9125-4566-9ba5-e4450e10f30e CSeq: 2778 ACK Route: Route: Max-Forwards: 70 User-Agent: PBX Content-Length: 0 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f492806faa8) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONFIRMED [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000001)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3147 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f492806faa8 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Terminated [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is RX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONFIRMED [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 200 OK -- PJSIP/proxy-00000001 answered PJSIP/proxy-00000000 [Nov 23 12:13:21] DEBUG[28199]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy [Nov 23 12:13:21] DEBUG[28199]: devicestate.c:472 do_state_change: Changing state for PJSIP/proxy - state 2 (In use) -- PJSIP/proxy-00000001 Internal Gosub(dial-answered,s,1) start [Nov 23 12:13:21] DEBUG[28252][C-00000001]: app_stack.c:1004 gosub_run: PJSIP/proxy-00000001 Original location: from-proxy,,1 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: app_stack.c:1008 gosub_run: Gosub exited with status 0 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx_variables.c:376 ast_str_retrieve_variable: Result of 'vm_detect' is NULL [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@dial-answered:1] GotoIf("PJSIP/proxy-00000001", "?2:3") in new stack -- Goto (dial-answered,s,3) [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'NoOp' -- Executing [s@dial-answered:3] NoOp("PJSIP/proxy-00000001", "Finish if_dial-answered_99") in new stack [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx_variables.c:706 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '~~s~~' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx_variables.c:775 pbx_substitute_variables_helper_full: Expression result is '0' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@dial-answered:4] GotoIf("PJSIP/proxy-00000001", "0?5:18") in new stack -- Goto (dial-answered,s,18) [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx_variables.c:379 ast_str_retrieve_variable: Result of 'start_recording_on_answer' is '0' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx_variables.c:775 pbx_substitute_variables_helper_full: Expression result is '0' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@dial-answered:18] GotoIf("PJSIP/proxy-00000001", "0?19:20") in new stack -- Goto (dial-answered,s,20) [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'NoOp' -- Executing [s@dial-answered:20] NoOp("PJSIP/proxy-00000001", "Finish if_if_dial-answered_100_103") in new stack [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'NoOp' -- Executing [s@dial-answered:21] NoOp("PJSIP/proxy-00000001", "Finish if_dial-answered_100") in new stack [Nov 23 12:13:21] DEBUG[28252][C-00000001]: pbx.c:2915 pbx_extension_helper: Launching 'Return' -- Executing [s@dial-answered:22] Return("PJSIP/proxy-00000001", "") in new stack [Nov 23 12:13:21] DEBUG[28252][C-00000001]: app_stack.c:1066 gosub_run: Spawn extension (from-proxy,,1) exited with -1 on 'PJSIP/proxy-00000001' == Spawn extension (from-proxy, , 1) exited non-zero on 'PJSIP/proxy-00000001' -- PJSIP/proxy-00000001 Internal Gosub(dial-answered,s,1) complete GOSUB_RETVAL= [Nov 23 12:13:21] DEBUG[28252][C-00000001]: app_stack.c:1092 gosub_run: PJSIP/proxy-00000001 Ending location: from-proxy,,1 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting read format path: alaw -> slin16 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting write format path: slin16 -> g722 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting read format path: g722 -> slin16 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: channel.c:5551 set_format: Channel PJSIP/proxy-00000001 setting write format path: slin16 -> alaw [Nov 23 12:13:21] DEBUG[28199]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - proxy [Nov 23 12:13:21] DEBUG[28199]: devicestate.c:472 do_state_change: Changing state for PJSIP/proxy - state 2 (In use) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3235 handle_outgoing_response: Method is INVITE, Response is 200 OK [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP response (1376 bytes) to UDP:1.6.1.6:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8065;rport=8065;received=1.6.1.6;branch=z9hG4bK5be3.4d42378d68478edd69ae44f093b8724e.0 Via: SIP/2.0/UDP 1.6.1.6:8060;branch=z9hG4bK5be3.1fe0e8eafad7b826a80fda10e5f811dd.0 Via: SIP/2.0/UDP 1.1.1.9:5060;rport=5060;received=4.1.3.1;branch=z9hG4bK-373138-74a8aff9eb199ecdaeee4ca385e30dc9 Record-Route: Record-Route: Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 From: "phone_27407_0" ;tag=e507bbb7 To: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 CSeq: 2 INVITE Server: PBX Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 356 v=0 o=- 0 2 IN IP4 1.6.1.6 s=Asterisk c=IN IP4 1.6.1.6 t=0 0 m=audio 38636 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 25680 RTP/AVP 105 a=rtpmap:105 H264/90000 a=sendonly [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f4928017ef8) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONNECTING [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3359 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f4928017ef8) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f4928017ef8 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Completed [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is TX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONNECTING [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:725 native_rtp_bridge_compatible: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0' can not use native RTP bridge as two channels are required [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:809 bridge_base_init: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: calling simple_bridge technology constructor [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:817 bridge_base_init: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: calling simple_bridge technology start [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge_channel.c:2792 bridge_channel_internal_join: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: 0x7f492c0296d8(PJSIP/proxy-00000001) is joining [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge_channel.c:2188 bridge_channel_internal_push_full: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: pushing 0x7f492c0296d8(PJSIP/proxy-00000001) -- Channel PJSIP/proxy-00000001 joined 'simple_bridge' basic-bridge <44cbea60-4b51-49ca-b35a-953244dd49b0> [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge_native_rtp.c:725 native_rtp_bridge_compatible: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0' can not use native RTP bridge as two channels are required [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:1063 smart_bridge_operation: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0 is already using the new technology. [Nov 23 12:13:21] DEBUG[28256][C-00000001]: bridge.c:430 bridge_channel_complete_join: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: 0x7f492c0296d8(PJSIP/proxy-00000001) is joining simple_bridge technology <--- Received SIP request (779 bytes) from UDP:1.6.1.6:8065 ---> ACK sip:1.6.1.6:8066 SIP/2.0 Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 CSeq: 2 ACK Via: SIP/2.0/UDP 1.6.1.6:8065;branch=z9hG4bK5be3.f506aaf45c9abc2d01948c29c0b7597b.0 Via: SIP/2.0/UDP 1.6.1.6:8060;branch=z9hG4bK5be3.7850f42eaebfee0ef483987e3b7e17cc.0 Via: SIP/2.0/UDP 1.1.1.9:5060;rport=5060;received=4.1.3.1;branch=z9hG4bK-373138-7da8fc7eab35c6a9ac456636b7d6ad61 From: "phone_27407_0" ;tag=e507bbb7 To: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 Max-Forwards: 68 m: User-Agent: Jitsi2.10.5550Linux Content-Length: 0 [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f4928015d18 for Request msg ACK/cseq=2 (rdata0x7f4920008d28) [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000039 associated with dialog dlg0x7f4928015d18 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3147 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f4928017ef8 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Terminated [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is USER [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONNECTING [Nov 23 12:13:21] DEBUG[28256][C-00000001]: channel.c:10861 ast_channel_request_stream_topology_change: Topology of PJSIP/proxy-00000001 already matches what is requested so ignoring topology change request [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3147 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3159 __print_debug_details: There is no transaction involved in this state change [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONFIRMED [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received request [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3171 handle_incoming_request: Method is ACK [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_channel.c:2792 bridge_channel_internal_join: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: 0x7f492c014888(PJSIP/proxy-00000000) is joining [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_channel.c:2188 bridge_channel_internal_push_full: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: pushing 0x7f492c014888(PJSIP/proxy-00000000) -- Channel PJSIP/proxy-00000000 joined 'simple_bridge' basic-bridge <44cbea60-4b51-49ca-b35a-953244dd49b0> [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:615 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0'. Checking compatability for channels 'PJSIP/proxy-00000001' and 'PJSIP/proxy-00000000' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:642 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0' can not use native RTP bridge as it was forbidden while getting details [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:1063 smart_bridge_operation: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0 is already using the new technology. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:430 bridge_channel_complete_join: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0: 0x7f492c014888(PJSIP/proxy-00000000) is joining simple_bridge technology [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f492800f398' [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f4928011238' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:1628 ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to proxy [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3220 handle_outgoing_request: Method is INVITE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '1.6.1.6' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '1.6.1.6' is 'UDP' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '1.6.1.6' is an IP address, skipping resolution [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (1261 bytes) to UDP:1.6.1.6:8065 ---> INVITE sip:phone_27407_0@1.1.1.9:5060;transport=udp;registering_acc=sip_everest_dev_com;alias="4.1.3.1:5060" SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPjbb518765-5fb7-44c0-8185-56bf95bca72c From: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 To: "phone_27407_0" ;tag=e507bbb7 Contact: Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 CSeq: 32216 INVITE Route: Route: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: PBX Content-Type: application/sdp Content-Length: 332 v=0 o=- 0 3 IN IP4 1.6.1.6 s=Asterisk c=IN IP4 1.6.1.6 t=0 0 m=audio 38636 RTP/AVP 8 0 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 25680 RTP/AVP 105 a=rtpmap:105 H264/90000 a=sendrecv [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3144 __print_debug_details: The inv session still has an invite_tsx (0x7f4928017ef8) [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f4928017ef8 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Calling [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is TX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONFIRMED [Nov 23 12:13:21] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:4920 ast_rtcp_interpret: Got RTCP report of 96 bytes from 4.1.3.1:5009 [Nov 23 12:13:21] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.1.3.1:5009' into... [Nov 23 12:13:21] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.1.3.1' and port '5009'. [Nov 23 12:13:21] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:38637' into... [Nov 23 12:13:21] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '38637'. <--- Received SIP response (1104 bytes) from UDP:1.6.1.6:8065 ---> SIP/2.0 200 OK CSeq: 32216 INVITE Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 From: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 To: "phone_27407_0" ;tag=e507bbb7 Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPjbb518765-5fb7-44c0-8185-56bf95bca72c m: User-Agent: Jitsi2.10.5550Linux Content-Type: application/sdp Content-Length: 540 v=0 o=phone_27407_0-jitsi.org 0 1 IN IP4 1.1.1.9 s=- c=IN IP4 1.1.1.9 t=0 0 m=audio 5008 RTP/AVP 8 0 3 101 a=direction:passive a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=zrtp-hash:1.10 388a1bd978bed3c9dc8de6b3786a888c833abd66c677481f91ce238c98d79c29 m=video 5010 RTP/AVP 99 a=recvonly a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=4DE01f a=imageattr:99 send * recv * a=zrtp-hash:1.10 a6c0590daca65ceb7d7da70ab2bb7ce916510641f9769d4cf99883af765a9e80 [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f4928015d18 for Response msg 200/INVITE/cseq=32216 (rdata0x7f4920008d28) [Nov 23 12:13:21] DEBUG[28214]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000039 associated with dialog dlg0x7f4928015d18 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f492800f398' [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.9' into... [Nov 23 12:13:21] DEBUG[28252][C-00000001]: chan_pjsip.c:802 chan_pjsip_read_stream: Oooh, got a frame with format of alaw on channel 'PJSIP/proxy-00000000' when it has not been negotiated [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.9' and port ''. [Nov 23 12:13:21] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.9', our source address is '1.6.1.6'. [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f492800f398' > 0x7f4928020620 -- Strict RTP learning after remote address set to: 1.1.1.9:5008 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f48ecb72d30 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f48ecb72d30 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f48ecb72d30 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f48ecb72d30 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f49280074e0) from 0x7f48ecb72d30 to 0x7f492800f560 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 3 (0x7f4928074b80) from 0x7f48ecb72d30 to 0x7f492800f560 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7f492801f340) from 0x7f48ecb72d30 to 0x7f492800f560 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x23fd990) from 0x7f48ecb72d30 to 0x7f492800f560 [Nov 23 12:13:21] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting read format path: alaw -> slin16 [Nov 23 12:13:21] DEBUG[28215]: channel.c:5551 set_format: Channel PJSIP/proxy-00000000 setting write format path: slin16 -> alaw [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:615 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0'. Checking compatability for channels 'PJSIP/proxy-00000001' and 'PJSIP/proxy-00000000' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:642 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0' can not use native RTP bridge as it was forbidden while getting details [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:1063 smart_bridge_operation: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0 is already using the new technology. [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:738 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6036 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f4928011238' [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.9' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.9' and port ''. [Nov 23 12:13:21] DEBUG[28215]: acl.c:955 ast_ouraddrfor: For destination '1.1.1.9', our source address is '1.6.1.6'. [Nov 23 12:13:21] DEBUG[28215]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f4928011238' > 0x7f4928037d70 -- Strict RTP learning after remote address set to: 1.1.1.9:5010 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:1032 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 99 based on m type on 0x7f48ecb72d30 [Nov 23 12:13:21] DEBUG[28215]: rtp_engine.c:921 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 99 (0x7f4928073250) from 0x7f48ecb72d30 to 0x7f4928011400 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:615 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0'. Checking compatability for channels 'PJSIP/proxy-00000001' and 'PJSIP/proxy-00000000' [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge_native_rtp.c:642 native_rtp_bridge_compatible_check: Bridge '44cbea60-4b51-49ca-b35a-953244dd49b0' can not use native RTP bridge as it was forbidden while getting details [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge [Nov 23 12:13:21] DEBUG[28252][C-00000001]: bridge.c:1063 smart_bridge_operation: Bridge 44cbea60-4b51-49ca-b35a-953244dd49b0 is already using the new technology. [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:743 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'video' using video SDP handler [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '1.6.1.6' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '1.6.1.6' is 'UDP' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '1.6.1.6' is an IP address, skipping resolution [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:21] DEBUG[28252][C-00000001]: acl.c:955 ast_ouraddrfor: For destination '4.1.3.1', our source address is '1.6.1.6'. [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8065' into... [Nov 23 12:13:21] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8065'. <--- Transmitting SIP request (669 bytes) to UDP:1.6.1.6:8065 ---> ACK sip:phone_27407_0@1.1.1.9:5060;transport=udp;registering_acc=sip_everest_dev_com;alias="4.1.3.1:5060" SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPje9dc753e-62c3-41ec-9e26-a5d445faa00f From: ;tag=bcf4e29b-59f5-4ceb-89c8-76077ee06bd6 To: "phone_27407_0" ;tag=e507bbb7 Call-ID: 82dc4baba9fa55141d8bb01d2e674b98@0:0:0:0:0:0:0:0 CSeq: 32216 ACK Route: Route: Max-Forwards: 70 User-Agent: PBX Content-Length: 0 [Nov 23 12:13:21] DEBUG[28252][C-00000001]: res_rtp_asterisk.c:6201 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f492800f398' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3125 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3139 __print_debug_details: The state change pertains to the endpoint 'proxy(PJSIP/proxy-00000000)' [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3147 __print_debug_details: The inv session does NOT have an invite_tsx [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3150 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f4928017ef8 [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3154 __print_debug_details: The current transaction state is Terminated [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3156 __print_debug_details: The transaction state change event is RX_MSG [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3161 __print_debug_details: The current inv state is CONFIRMED [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3204 handle_incoming: Received response [Nov 23 12:13:21] DEBUG[28215]: res_pjsip_session.c:3188 handle_incoming_response: Response is 200 OK [Nov 23 12:13:21] DEBUG[28252][C-00000001]: channel.c:3749 __ast_read: Dropping duplicate answer! [Nov 23 12:13:21] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. > 0x7f4928020620 -- Strict RTP learning complete - Locking on source address 4.1.3.1:5008 [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:22] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:23] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3765 endpt_send_request: 0x7f4928073478: Wrapper created [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3780 endpt_send_request: 0x7f4928073478: Set timer to 3000 msec [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target 'proxy.dev.com' [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target 'proxy.dev.com' is 'UDP' [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:547 sip_resolve: [0x7f4928068fa0] Created resolution tracking for target 'proxy.dev.com' [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:177 sip_resolve_add: [0x7f4928068fa0] Added target 'proxy.dev.com' with record type '1', transport 'UDP', and port '8065' [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:613 sip_resolve: [0x7f4928068fa0] Starting initial resolution using parallel queries for target 'proxy.dev.com' [Nov 23 12:13:24] DEBUG[28201]: res_pjsip/pjsip_resolver.c:277 sip_resolve_callback: [0x7f4928068fa0] All parallel queries completed [Nov 23 12:13:24] DEBUG[28201]: res_pjsip/pjsip_resolver.c:326 sip_resolve_callback: [0x7f4928068fa0] A record received on target 'proxy.dev.com' [Nov 23 12:13:24] DEBUG[28201]: res_pjsip/pjsip_resolver.c:419 sip_resolve_callback: [0x7f4928068fa0] Resolution completed - 1 viable targets [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:201 sip_resolve_invoke_user_callback: [0x7f4928068fa0] Address '0' is 1.1.5.2:8065 with transport 'UDP' [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_resolver.c:207 sip_resolve_invoke_user_callback: [0x7f4928068fa0] Invoking user callback with '1' addresses [Nov 23 12:13:24] DEBUG[28215]: res_pjsip/pjsip_message_ip_updater.c:287 multihomed_on_tx_message: Re-wrote Contact URI host/port to 1.6.1.6:8066 [Nov 23 12:13:24] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:24] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:24] DEBUG[28215]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.5.2:8065' into... [Nov 23 12:13:24] DEBUG[28215]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.5.2' and port '8065'. <--- Transmitting SIP request (475 bytes) to UDP:1.1.5.2:8065 ---> OPTIONS sip:proxy.dev.com:8065 SIP/2.0 Via: SIP/2.0/UDP 1.6.1.6:8066;rport;branch=z9hG4bKPj99bb4b5f-809b-4358-b79c-3e42742f0f43 From: ;tag=3a372f1a-03b8-4d31-8f38-cc32a4a49927 To: Contact: Call-ID: 59141fb9-f425-497c-b2ce-f920c325fe70 CSeq: 46749 OPTIONS Max-Forwards: 70 User-Agent: PBX Content-Length: 0 [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. <--- Received SIP response (476 bytes) from UDP:1.1.5.2:8065 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.6.1.6:8066;rport=8066;branch=z9hG4bKPj99bb4b5f-809b-4358-b79c-3e42742f0f43 From: ;tag=3a372f1a-03b8-4d31-8f38-cc32a4a49927 To: ;tag=d4d563dde07c0116b8df5fecd2d4dcf7.dfc8 Call-ID: 59141fb9-f425-497c-b2ce-f920c325fe70 CSeq: 46749 OPTIONS Accept: */* Accept-Encoding: Accept-Language: en Supported: Server: Proxy 2 Content-Length: 0 [Nov 23 12:13:24] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.5.2:8065' into... [Nov 23 12:13:24] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.5.2' and port '8065'. [Nov 23 12:13:24] DEBUG[28214]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:8066' into... [Nov 23 12:13:24] DEBUG[28214]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '8066'. [Nov 23 12:13:24] DEBUG[28214]: res_pjsip/pjsip_distributor.c:519 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=46749 (rdata0x7f4920008d28). Using request transaction as basis. [Nov 23 12:13:24] DEBUG[28214]: res_pjsip/pjsip_distributor.c:127 find_request_serializer: Found transaction tsx0x7f4928017ef8 for Response msg 200/OPTIONS/cseq=46749 (rdata0x7f4920008d28). [Nov 23 12:13:24] DEBUG[28214]: res_pjsip/pjsip_distributor.c:137 find_request_serializer: Found serializer pjsip/default-0000000f on transaction tsx0x7f4928017ef8 [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3643 endpt_send_request_cb: 0x7f4928073478: PJSIP tsx response received [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3656 endpt_send_request_cb: 0x7f4928073478: Cancelling timer [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3665 endpt_send_request_cb: 0x7f4928073478: Timer cancelled [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 23 12:13:24] DEBUG[28215]: config.c:3740 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3686 endpt_send_request_cb: 0x7f4928073478: Callbacks executed [Nov 23 12:13:24] DEBUG[28215]: res_pjsip.c:3742 send_request_wrapper_destructor: 0x7f4928073478: wrapper destroyed [Nov 23 12:13:24] DEBUG[28223]: res_pjsip/pjsip_configuration.c:281 persistent_endpoint_contact_status_observer: Contact proxy-1.1.5.2/sip:proxy.dev.com:8065 status didn't change: Reachable, RTT: 9.309 msec [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28256][C-00000001]: res_rtp_asterisk.c:5706 ast_rtp_read: 0x7f4928027e70 -- Received RTP packet from 8.2.1.8:12796, dropping due to strict RTP protection. [Nov 23 12:13:24] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.6.1.6:29353' into... [Nov 23 12:13:24] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.6.1.6' and port '29353'. [Nov 23 12:13:24] DEBUG[28239]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.2:19141' into... [Nov 23 12:13:24] DEBUG[28239]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.2' and port '19141'.