debug.txt

Asterisk 15.5.0~dfsg-1.1ubuntu4.8, Copyright (C) 1999 - 2016, Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 15.5.0~dfsg-1.1ubuntu4.8 currently running on callcenter (pid = 15771)
[Sep 11 11:36:53] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.50:5080
[Sep 11 11:36:54] DEBUG[6490]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket pong frame, length 0
[Sep 11 11:36:54] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.49:5060
[Sep 11 11:36:54] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.48:5060
[Sep 11 11:36:54] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:54] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000025 to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:54] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:54] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:54] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:54] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000034 to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:54] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.17' into...
[Sep 11 11:36:54] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.17' and port ''.
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.17:5060 matches identify 'in'
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'in' SIP message matched to endpoint in
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:54] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:54] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.50:5080
[Sep 11 11:36:54] DEBUG[16588]: chan_sip.c:6595 sip_pvt_dtor: Destroying SIP dialog 457a28c03175844355345a08146f6cb6@192.168.0.20:5080
[Sep 11 11:36:55] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.49:5060
[Sep 11 11:36:55] DEBUG[16588]: chan_sip.c:6595 sip_pvt_dtor: Destroying SIP dialog 131cc9e455d89aa57166a28d7244a14e@192.168.0.20:5080
[Sep 11 11:36:55] DEBUG[16588]: chan_sip.c:3754 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.56.48:5060
[Sep 11 11:36:55] DEBUG[16588]: chan_sip.c:6595 sip_pvt_dtor: Destroying SIP dialog 144d12fe65fca020699ebe7e681ce128@192.168.0.20:5080
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000002b to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:55] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:55] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:55] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:55] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:55] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in()'
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3252 __print_debug_details: The inv session does NOT have an invite_tsx
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3255 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7f334c28dd18
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Terminated
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is TIMER
[Sep 11 11:36:55] DEBUG[16550]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is DISCONNCTD
[Sep 11 11:36:55] DEBUG[22397]: res_pjsip_session.c:2071 session_destructor: Destroying SIP session with endpoint in
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=2 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=2 (rdata0x7f335021b438)
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3346 handle_outgoing_response: Method is INVITE, Response is 100 Trying
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents()'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c28dd18)
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is INCOMING
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3475 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents()'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c28dd18)
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f334c28dd18
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Proceeding
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is TX_MSG
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is INCOMING
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:761 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.162' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.162' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:505 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f334c0317f8'
[Sep 11 11:36:56] DEBUG[22397]: res_rtp_asterisk.c:3481 rtp_allocate_transport: Allocated port 12974 for RTP instance '0x7f334c0317f8'
[Sep 11 11:36:56] DEBUG[22397]: res_rtp_asterisk.c:3509 rtp_allocate_transport: Creating ICE session [::]:12974 (12974) for RTP instance '0x7f334c0317f8'
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.20' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.20' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.20' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.20' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.0.3.1' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.0.3.1' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.0.3.1' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.0.3.1' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:522 ast_rtp_instance_new: RTP instance '0x7f334c0317f8' is setup and ready to go
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'callcenter' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'callcenter' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: res_rtp_asterisk.c:6823 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f334c0317f8'
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1262 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 0 (0x7f334c003dc0) from 0x7f336055f440 to 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1262 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 8 (0x7f334c2905e0) from 0x7f336055f440 to 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1262 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 18 (0x7f334c1339d0) from 0x7f336055f440 to 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1262 ast_rtp_codecs_payloads_xover: Crossover copying tx to rx payload mapping 101 (0x7f334c25cfc0) from 0x7f336055f440 to 0x7f336055f440
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1099 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 0 (0x7f334c003dc0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1099 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 8 (0x7f334c2905e0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1099 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 18 (0x7f334c1339d0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1099 rtp_codecs_payloads_copy_rx: Copying rx payload mapping 101 (0x7f334c25cfc0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f334c003dc0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7f334c2905e0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 18 (0x7f334c1339d0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7f334c25cfc0) from 0x7f336055f440 to 0x7f334c0319d0
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:774 handle_incoming_sdp: Media stream 'audio' handled by audio
[Sep 11 11:36:56] DEBUG[22397]: res_rtp_asterisk.c:6722 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f334c0317f8'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:3276 handle_incoming_request: Method is INVITE
[Sep 11 11:36:56] DEBUG[22397]: channel.c:1001 __ast_channel_alloc_ap: Channel 0x7f334c2b3e78 'PJSIP/agents-0000004c' allocated
[Sep 11 11:36:56] DEBUG[22397]: chan_pjsip.c:2975 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/agents-0000004c
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: pbx.c:2917 pbx_extension_helper: Launching 'NoOp'
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: pbx_variables.c:772 pbx_substitute_variables_helper_full: Function PJSIP_HEADER(read,X-APP-user) result is '1'
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: pbx_variables.c:772 pbx_substitute_variables_helper_full: Function PJSIP_HEADER(read,Call-ID) result is 'YWYyYzg3NDkzOWE4YzI2MGZjNjE1N2Q3NTAzOGJlZWE.'
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: pbx_variables.c:772 pbx_substitute_variables_helper_full: Function CHANNEL(LINKEDID) result is '1536665816.206'
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: pbx.c:2917 pbx_extension_helper: Launching 'Stasis'
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: stasis/app.c:1295 app_subscribe_channel: Channel '1536665816.206' is 1 interested in APP
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 510
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 510
[Sep 11 11:36:56] DEBUG[6574]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6574]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30&type=mixing
[Sep 11 11:36:56] DEBUG[6574]: http.c:1445 handle_uri: match request [ari/bridges] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6574]: http.c:1445 handle_uri: match request [ari/bridges] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6574]: http.c:1445 handle_uri: match request [ari/bridges] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6574]: http.c:1445 handle_uri: match request [ari/bridges] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6574]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6574]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6574]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as two channels are required
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:512 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:809 bridge_base_init: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology constructor
[Sep 11 11:36:56] DEBUG[6574]: bridge.c:817 bridge_base_init: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology start
[Sep 11 11:36:56] DEBUG[6574]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:200
[Sep 11 11:36:56] DEBUG[6574]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6575]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6575]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30-recording&type=mixing
[Sep 11 11:36:56] DEBUG[6575]: http.c:1445 handle_uri: match request [ari/bridges] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6575]: http.c:1445 handle_uri: match request [ari/bridges] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6575]: http.c:1445 handle_uri: match request [ari/bridges] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6575]: http.c:1445 handle_uri: match request [ari/bridges] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6575]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6575]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6575]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording' can not use native RTP bridge as two channels are required
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:512 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:809 bridge_base_init: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: calling simple_bridge technology constructor
[Sep 11 11:36:56] DEBUG[6575]: bridge.c:817 bridge_base_init: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: calling simple_bridge technology start
[Sep 11 11:36:56] DEBUG[6575]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:200
[Sep 11 11:36:56] DEBUG[6575]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6576]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6576]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1536665816.206/variable?api_key=XXXXXX&app=APP&channelId=1536665816.206&value=0&variable=CHANNEL%28musicclass%29
[Sep 11 11:36:56] DEBUG[6576]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6576]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6576]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6576]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6576]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:513 ast_ari_invoke: Finding handler for 1536665816.206
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:513 ast_ari_invoke: Finding handler for variable
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:56] DEBUG[6576]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6576]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6576]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6577]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6577]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/create?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30&endpoint=PJSIP%2F1-5001%40in
[Sep 11 11:36:56] DEBUG[6577]: http.c:1445 handle_uri: match request [ari/channels/create] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6577]: http.c:1445 handle_uri: match request [ari/channels/create] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6577]: http.c:1445 handle_uri: match request [ari/channels/create] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6577]: http.c:1445 handle_uri: match request [ari/channels/create] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6577]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:513 ast_ari_invoke: Finding handler for create
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6577]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6577]: channel.c:1001 __ast_channel_alloc_ap: Channel 0x7f335c0136f8 'PJSIP/in-0000004d' allocated
[Sep 11 11:36:56] DEBUG[6577]: res_stasis.c:1838 stasis_app_subscribe_channel: APP: Subscribing to out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6577]: stasis/app.c:1295 app_subscribe_channel: Channel 'out-31151dda-0502-4283-be18-79cf21414d30' is 1 interested in APP
[Sep 11 11:36:56] DEBUG[6577]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:200
[Sep 11 11:36:56] DEBUG[6578]: stasis/app.c:1295 app_subscribe_channel: Channel 'out-31151dda-0502-4283-be18-79cf21414d30' is 2 interested in APP
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 495
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 495
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 475
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 475
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 446
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 446
[Sep 11 11:36:56] DEBUG[6577]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6579]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6579]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1536665816.206/variable?api_key=XXXXXX&app=APP&channelId=1536665816.206&value=1234567890&variable=CALLERID%28number%29
[Sep 11 11:36:56] DEBUG[6579]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6579]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6579]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6579]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6579]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:513 ast_ari_invoke: Finding handler for 1536665816.206
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:513 ast_ari_invoke: Finding handler for variable
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:56] DEBUG[6579]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6579]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6579]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6580]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6580]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1536665816.206/variable?api_key=XXXXXX&app=APP&channelId=1536665816.206&value=KT&variable=CALLERID%28name%29
[Sep 11 11:36:56] DEBUG[6580]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6580]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6580]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6580]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/variable] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6580]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:513 ast_ari_invoke: Finding handler for 1536665816.206
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:513 ast_ari_invoke: Finding handler for variable
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:56] DEBUG[6580]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6580]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6580]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6581]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6581]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30&value=YWYyYzg3NDkzOWE4YzI2MGZjNjE1N2Q3NTAzOGJlZWE.&variable=PJSIP_HEADER%28add%2CX-CID%29
[Sep 11 11:36:56] DEBUG[6581]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6581]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6581]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6581]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6581]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:513 ast_ari_invoke: Finding handler for variable
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:56] DEBUG[6581]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6581]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6581]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6582]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6582]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30&value=%7B%22type%22%3A%22manual%22%2C%22callcenter%22%3A1%2C%22agent%22%3A%221%22%2C%22site_name%22%3A%22test%22%7D&variable=PJSIP_HEADER%28add%2CX-vector%29
[Sep 11 11:36:56] DEBUG[6582]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6582]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6582]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6582]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/variable] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6582]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:513 ast_ari_invoke: Finding handler for variable
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:56] DEBUG[6582]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6582]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6582]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6583]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6583]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30&channel=1536665816.206
[Sep 11 11:36:56] DEBUG[6583]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6583]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6583]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6583]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6583]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:513 ast_ari_invoke: Finding handler for 31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking bridgeId
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:513 ast_ari_invoke: Finding handler for addChannel
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:518 ast_ari_invoke:   Checking addChannel
[Sep 11 11:36:56] DEBUG[6583]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6583]: stasis/control.c:1295 stasis_app_control_add_channel_to_bridge: 1536665816.206: Sending channel add_to_bridge command
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000001e to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.17' into...
[Sep 11 11:36:56] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.17' and port ''.
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.17:5060 matches identify 'in'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'in' SIP message matched to endpoint in
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: bridge_roles.c:367 ast_channel_clear_bridge_roles: Roles did not exist on channel PJSIP/agents-0000004c
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: stasis/control.c:1211 control_swap_channel_in_bridge: 1536665816.206: Adding to bridge 31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30' is 1 interested in APP
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 522
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 522
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 524
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 524
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is joining
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge 31151dda-0502-4283-be18-79cf21414d30: pushing 0x7f3350294998(PJSIP/agents-0000004c)
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as two channels are required
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is joining simple_bridge technology
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 654
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 654
[Sep 11 11:36:56] DEBUG[6573][C-00000033]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30' is 2 interested in APP
[Sep 11 11:36:56] DEBUG[6583]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6583]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6585]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:56] DEBUG[6585]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30&channel=out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6585]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [httpstatus] len 10
[Sep 11 11:36:56] DEBUG[6585]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [phoneprov] len 9
[Sep 11 11:36:56] DEBUG[6585]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [static] len 6
[Sep 11 11:36:56] DEBUG[6585]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30/addChannel] with handler [ari] len 3
[Sep 11 11:36:56] DEBUG[6585]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:513 ast_ari_invoke: Finding handler for 31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking bridgeId
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:513 ast_ari_invoke: Finding handler for addChannel
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:518 ast_ari_invoke:   Checking addChannel
[Sep 11 11:36:56] DEBUG[6585]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:56] DEBUG[6585]: stasis/control.c:1295 stasis_app_control_add_channel_to_bridge: out-31151dda-0502-4283-be18-79cf21414d30: Sending channel add_to_bridge command
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_header_funcs.c:340 add_header: Adding header X-CID with value YWYyYzg3NDkzOWE4YzI2MGZjNjE1N2Q3NTAzOGJlZWE.
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_header_funcs.c:340 add_header: Adding header X-vector with value {"type":"manual","callcenter":1,"agent":"1","site_name":"test"}
[Sep 11 11:36:56] DEBUG[6578]: bridge_roles.c:367 ast_channel_clear_bridge_roles: Roles did not exist on channel PJSIP/in-0000004d
[Sep 11 11:36:56] DEBUG[6578]: stasis/control.c:1211 control_swap_channel_in_bridge: out-31151dda-0502-4283-be18-79cf21414d30: Adding to bridge 31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:56] DEBUG[6578]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30' is 3 interested in APP
[Sep 11 11:36:56] DEBUG[6586]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is joining
[Sep 11 11:36:56] DEBUG[6586]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge 31151dda-0502-4283-be18-79cf21414d30: pushing 0x3c2fee8(PJSIP/in-0000004d)
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:56] DEBUG[6586]: bridge_native_rtp.c:628 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/agents-0000004c' has features which prevent it
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:56] DEBUG[6586]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is joining simple_bridge technology
[Sep 11 11:36:56] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting read format path: ulaw -> ulaw
[Sep 11 11:36:56] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting write format path: ulaw -> ulaw
[Sep 11 11:36:56] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting read format path: ulaw -> ulaw
[Sep 11 11:36:56] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting write format path: ulaw -> ulaw
[Sep 11 11:36:56] DEBUG[16525]: cdr.c:1462 cdr_object_finalize: Finalized CDR for PJSIP/in-0000004d - start 1536665816.760783 answer 0.000000 end 1536665816.963003 dispo FAILED
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 700
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 700
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 487
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 487
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 511
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 511
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 494
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 494
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 522
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 522
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 457
[Sep 11 11:36:56] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 457
[Sep 11 11:36:56] DEBUG[6584][C-00000033]: channel.c:4368 indicate_connected_line: PJSIP/agents-0000004c: Dropping redundant connected line update "" <>.
[Sep 11 11:36:56] DEBUG[6578]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30' is 4 interested in APP
[Sep 11 11:36:56] DEBUG[22397]: res_pjsip_session.c:1489 ast_sip_session_refresh: Delay sending request to in because dialog has not been established...
[Sep 11 11:36:56] DEBUG[6585]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:56] DEBUG[6585]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:56] DEBUG[6587]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6587]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/dial?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30&timeout=100
[Sep 11 11:36:57] DEBUG[6587]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/dial] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6587]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/dial] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6587]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/dial] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6587]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/dial] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6587]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:513 ast_ari_invoke: Finding handler for dial
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking snoop
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:518 ast_ari_invoke:   Checking dial
[Sep 11 11:36:57] DEBUG[6587]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6587]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6578]: bridge.c:3399 ast_bridge_interval_hook: Putting interval hook 0x3c6f280 with interval 99999 in the heap on features 0x3cec120
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 492
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 492
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:505 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:3481 rtp_allocate_transport: Allocated port 15486 for RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:3509 rtp_allocate_transport: Creating ICE session [::]:15486 (15486) for RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.20' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.20' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.20' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.20' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.0.3.1' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.0.3.1' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '10.0.3.1' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '10.0.3.1' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:522 ast_rtp_instance_new: RTP instance '0x7f334c070078' is setup and ready to go
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'callcenter' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'callcenter' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6823 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3325 handle_outgoing_request: Method is INVITE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.0.20:5081 (this may be re-written again later)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c1bf318)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CALLING
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3475 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c1bf318)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c1bf318
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Calling
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CALLING
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:628 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/agents-0000004c' has features which prevent it
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 487
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 487
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 511
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 511
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 506
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 506
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 534
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 534
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f334c074f48 for Response msg 100/INVITE/cseq=26791 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/in-00000089 associated with dialog dlg0x7f334c074f48
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c1bf318)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c1bf318
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Proceeding
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CALLING
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received response
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3293 handle_incoming_response: Response is 100 trying -- your call is important to us
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3735 session_inv_on_tsx_state_changed: Endpoint 'in(PJSIP/in-0000004d)' INVITE delay check. tsx-state:Proceeding
[Sep 11 11:36:57] DEBUG[6587]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f334c074f48 for Response msg 200/INVITE/cseq=26791 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/in-00000089 associated with dialog dlg0x7f334c074f48
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c1bf318)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONNECTING
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3475 session_inv_on_state_changed: Source of transaction state change is RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received response
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3293 handle_incoming_response: Response is 200 OK
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:830 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6722 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '146.185.159.115' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '146.185.159.115' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: acl.c:990 ast_ouraddrfor: For destination '146.185.159.115', our source address is '192.168.0.20'.
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6891 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f336055ee30
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f334c25c040) from 0x7f336055ee30 to 0x7f334c070250
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7f334c050b70) from 0x7f336055ee30 to 0x7f334c070250
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:835 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c1bf318)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3252 __print_debug_details: The inv session does NOT have an invite_tsx
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c1bf318
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Terminated
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received response
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3293 handle_incoming_response: Response is 200 OK
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3746 session_inv_on_tsx_state_changed: Endpoint 'in(PJSIP/in-0000004d)' INVITE delay check. tsx-state:Terminated
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:1176 send_delayed_request: Endpoint 'in(PJSIP/in-0000004d)' sending delayed INVITE request.
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6722 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:1688 ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to in
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3325 handle_outgoing_request: Method is INVITE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.0.20:5081 (this may be re-written again later)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c03dbf8)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c03dbf8
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Calling
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:628 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/agents-0000004c' has features which prevent it
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[6586]: channel.c:3765 __ast_read: Dropping duplicate answer!
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f334c074f48 for Response msg 100/INVITE/cseq=26792 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/in-00000089 associated with dialog dlg0x7f334c074f48
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 487
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 487
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 511
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 511
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 506
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 506
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 534
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 534
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 453
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 453
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 487
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 487
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - in
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:472 do_state_change: Changing state for PJSIP/in - state 2 (In use)
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - agents
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:472 do_state_change: Changing state for PJSIP/agents - state 2 (In use)
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 438
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 438
[Sep 11 11:36:57] DEBUG[16603]: app_queue.c:2546 device_state_cb: Device 'PJSIP/in' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Sep 11 11:36:57] DEBUG[16603]: app_queue.c:2546 device_state_cb: Device 'PJSIP/agents' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c03dbf8)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c03dbf8
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Proceeding
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received response
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3293 handle_incoming_response: Response is 100 trying -- your call is important to us
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:830 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6722 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f334c0317f8'
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.162' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.162' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: acl.c:990 ast_ouraddrfor: For destination '192.168.0.162', our source address is '192.168.0.20'.
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6891 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f334c0317f8'
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f336055f010
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f336055f010
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f336055f010
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f334c071e50) from 0x7f336055f010 to 0x7f334c0319d0
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 8 (0x7f334c0c7fa0) from 0x7f336055f010 to 0x7f334c0319d0
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 18 (0x7f334c25c1a0) from 0x7f336055f010 to 0x7f334c0319d0
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7f334c25c300) from 0x7f336055f010 to 0x7f334c0319d0
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:835 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3346 handle_outgoing_response: Method is INVITE, Response is 200 OK
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.0.20:5081 (this may be re-written again later)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents(PJSIP/agents-0000004c)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c28dd18)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONNECTING
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3475 session_inv_on_state_changed: Source of transaction state change is TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents(PJSIP/agents-0000004c)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3249 __print_debug_details: The inv session still has an invite_tsx (0x7f334c28dd18)
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f334c28dd18
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Completed
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is TX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONNECTING
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f334c210088 for Request msg ACK/cseq=2 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000032 associated with dialog dlg0x7f334c210088
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents(PJSIP/agents-0000004c)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3252 __print_debug_details: The inv session does NOT have an invite_tsx
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7f334c28dd18
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Terminated
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is USER
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONNECTING
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'agents(PJSIP/agents-0000004c)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3252 __print_debug_details: The inv session does NOT have an invite_tsx
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3264 __print_debug_details: There is no transaction involved in this state change
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received request
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3276 handle_incoming_request: Method is ACK
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:512 find_best_technology: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:526 find_best_technology: Chose bridge technology native_rtp
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1112 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling native_rtp technology constructor
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1130 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: moving 0x7f3350294998(PJSIP/agents-0000004c) to dummy bridge temporarily
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1130 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: moving 0x3c2fee8(PJSIP/in-0000004d) to dummy bridge temporarily
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1147 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is leaving simple_bridge technology (dummy)
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1147 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is leaving simple_bridge technology (dummy)
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1164 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology stop
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is joining native_rtp technology
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:824 native_rtp_bridge_join: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Channel 'PJSIP/agents-0000004c' is joining bridge tech
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:772 native_rtp_bridge_framehook_attach: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Attaching hook data 0x7f3358014fa0 to 'PJSIP/agents-0000004c'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is joining native_rtp technology
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:824 native_rtp_bridge_join: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Channel 'PJSIP/in-0000004d' is joining bridge tech
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:772 native_rtp_bridge_framehook_attach: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Attaching hook data 0x7f335800aad0 to 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:312 native_rtp_bridge_start: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Tech starting 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d' with target 'none'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1175 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling native_rtp technology start
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1192 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology destructor
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:512 find_best_technology: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:526 find_best_technology: Chose bridge technology native_rtp
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:512 find_best_technology: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology native_rtp
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[6586]: res_rtp_asterisk.c:4725 ast_rtp_write: Ooh, format changed from none to ulaw
[Sep 11 11:36:57] DEBUG[6586]: res_rtp_asterisk.c:4505 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f334c074f48 for Response msg 200/INVITE/cseq=26792 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/outsess/in-00000089 associated with dialog dlg0x7f334c074f48
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:830 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6722 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '146.185.159.115' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '146.185.159.115' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: acl.c:990 ast_ouraddrfor: For destination '146.185.159.115', our source address is '192.168.0.20'.
[Sep 11 11:36:57] DEBUG[22397]: res_rtp_asterisk.c:6891 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f334c070078'
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1298 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f336055ee00
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 0 (0x7f334c134350) from 0x7f336055ee00 to 0x7f334c070250
[Sep 11 11:36:57] DEBUG[22397]: rtp_engine.c:1184 rtp_codecs_payloads_copy_tx: Copying tx payload mapping 101 (0x7f334c152d80) from 0x7f336055ee00 to 0x7f334c070250
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:835 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3230 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3244 __print_debug_details: The state change pertains to the endpoint 'in(PJSIP/in-0000004d)'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3252 __print_debug_details: The inv session does NOT have an invite_tsx
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3255 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f334c03dbf8
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3259 __print_debug_details: The current transaction state is Terminated
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3261 __print_debug_details: The transaction state change event is RX_MSG
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3266 __print_debug_details: The current inv state is CONFIRMED
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3309 handle_incoming: Received response
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_session.c:3293 handle_incoming_response: Response is 200 OK
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:512 find_best_technology: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology native_rtp
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[6586]: channel.c:3765 __ast_read: Dropping duplicate answer!
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[6600]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6600]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1536665816.206/answer?api_key=XXXXXX&app=APP&channelId=1536665816.206
[Sep 11 11:36:57] DEBUG[6600]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/answer] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6600]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/answer] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6600]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/answer] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6600]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/answer] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6600]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:513 ast_ari_invoke: Finding handler for 1536665816.206
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:513 ast_ari_invoke: Finding handler for answer
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6600]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6600]: res_stasis_answer.c:49 stasis_app_control_answer: 1536665816.206: Sending answer command
[Sep 11 11:36:57] DEBUG[6573][C-00000033]: res_stasis_answer.c:40 app_control_answer: 1536665816.206: Answering
[Sep 11 11:36:57] DEBUG[6600]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6600]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6601]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6601]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1536665816.206/hold?api_key=XXXXXX&app=APP&channelId=1536665816.206
[Sep 11 11:36:57] DEBUG[6601]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/hold] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6601]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/hold] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6601]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/hold] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6601]: http.c:1445 handle_uri: match request [ari/channels/1536665816.206/hold] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6601]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:513 ast_ari_invoke: Finding handler for 1536665816.206
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:513 ast_ari_invoke: Finding handler for hold
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6601]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6601]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6573][C-00000033]: bridge_native_rtp.c:312 native_rtp_bridge_start: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Tech starting 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d' with target 'PJSIP/agents-0000004c'
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - agents
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:472 do_state_change: Changing state for PJSIP/agents - state 2 (In use)
[Sep 11 11:36:57] DEBUG[6601]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6602]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6602]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/hold?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:57] DEBUG[6602]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/hold] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6602]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/hold] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6602]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/hold] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6602]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/hold] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6602]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:513 ast_ari_invoke: Finding handler for hold
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6602]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6602]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6578]: bridge_native_rtp.c:312 native_rtp_bridge_start: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Tech starting 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d' with target 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:367 _ast_device_state: No provider found, checking channel drivers for PJSIP - in
[Sep 11 11:36:57] DEBUG[16521]: devicestate.c:472 do_state_change: Changing state for PJSIP/in - state 2 (In use)
[Sep 11 11:36:57] DEBUG[6602]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6603]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6603]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/snoop?api_key=XXXXXX&app=APP&app=APP&appArgs=spy&channelId=out-31151dda-0502-4283-be18-79cf21414d30&snoopId=out-31151dda-0502-4283-be18-79cf21414d30-snoop&spy=both
[Sep 11 11:36:57] DEBUG[6603]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/snoop] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6603]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/snoop] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6603]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/snoop] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6603]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30/snoop] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6603]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:513 ast_ari_invoke: Finding handler for snoop
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking variable
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:518 ast_ari_invoke:   Checking snoop
[Sep 11 11:36:57] DEBUG[6603]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6603]: channel.c:1001 __ast_channel_alloc_ap: Channel 0x7f3358016568 'Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a' allocated
[Sep 11 11:36:57] DEBUG[6603]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:200
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:634 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/in-0000004d' has features which prevent it
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1112 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology constructor
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1130 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: moving 0x7f3350294998(PJSIP/agents-0000004c) to dummy bridge temporarily
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1130 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: moving 0x3c2fee8(PJSIP/in-0000004d) to dummy bridge temporarily
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1147 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is leaving native_rtp technology (dummy)
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:866 native_rtp_bridge_leave: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Channel 'PJSIP/agents-0000004c' is leaving bridge tech
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:807 native_rtp_bridge_framehook_detach: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Detaching hook data 0x7f335800f260 from 'PJSIP/agents-0000004c'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:435 native_rtp_bridge_stop: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Tech stopping 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d' with target 'none'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:529 native_rtp_bridge_stop: Discontinued RTP bridging of 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d' - media will flow through Asterisk core
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:115 native_rtp_bridge_channel_data_free: Destroying channel tech_pvt data 0x7f3358014fa0
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1147 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is leaving native_rtp technology (dummy)
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:866 native_rtp_bridge_leave: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Channel 'PJSIP/in-0000004d' is leaving bridge tech
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:807 native_rtp_bridge_framehook_detach: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Detaching hook data 0x7f3358007790 from 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:115 native_rtp_bridge_channel_data_free: Destroying channel tech_pvt data 0x7f335800aad0
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1164 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling native_rtp technology stop
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x7f3350294998(PJSIP/agents-0000004c) is joining simple_bridge technology
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30: 0x3c2fee8(PJSIP/in-0000004d) is joining simple_bridge technology
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/agents-0000004c setting read format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: channel.c:5656 set_format: Channel PJSIP/in-0000004d setting write format path: ulaw -> ulaw
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1175 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling simple_bridge technology start
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1192 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30: calling native_rtp technology destructor
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6586]: bridge_native_rtp.c:634 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/in-0000004d' has features which prevent it
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6586]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[6604]: stasis/app.c:1295 app_subscribe_channel: Channel 'out-31151dda-0502-4283-be18-79cf21414d30-snoop' is 1 interested in APP
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30'.  Checking compatability for channels 'PJSIP/agents-0000004c' and 'PJSIP/in-0000004d'
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge_native_rtp.c:634 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30' can not use native RTP bridge as channel 'PJSIP/in-0000004d' has features which prevent it
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6584][C-00000033]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30 is already using the new technology.
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 489
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 489
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 485
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 509
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 504
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 532
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 532
[Sep 11 11:36:57] DEBUG[6603]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6605]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6605]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30-snoop
[Sep 11 11:36:57] DEBUG[6605]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6605]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6605]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6605]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6605]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30-snoop
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:513 ast_ari_invoke: Finding handler for silence
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:57] DEBUG[6605]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6605]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6605]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6606]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6606]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence?api_key=XXXXXX&app=APP&channelId=out-31151dda-0502-4283-be18-79cf21414d30-snoop
[Sep 11 11:36:57] DEBUG[6606]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6606]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6606]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6606]: http.c:1445 handle_uri: match request [ari/channels/out-31151dda-0502-4283-be18-79cf21414d30-snoop/silence] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6606]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:513 ast_ari_invoke: Finding handler for out-31151dda-0502-4283-be18-79cf21414d30-snoop
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking create
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking channelId
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:513 ast_ari_invoke: Finding handler for silence
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking continue
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking redirect
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking answer
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking ring
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking dtmf
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking mute
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking hold
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:518 ast_ari_invoke:   Checking silence
[Sep 11 11:36:57] DEBUG[6606]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6606]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6606]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6604]: stasis/control.c:726 app_control_silence_start: out-31151dda-0502-4283-be18-79cf21414d30-snoop: Starting silence generator
[Sep 11 11:36:57] DEBUG[6604]: channel.c:5656 set_format: Channel Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a setting write format path: slin -> slin
[Sep 11 11:36:57] DEBUG[6604]: channel.c:3194 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Sep 11 11:36:57] DEBUG[6604]: channel.c:8080 ast_channel_start_silence_generator: Started silence generator on 'Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a'
[Sep 11 11:36:57] DEBUG[6604]: stasis/control.c:747 control_silence_stop_now: out-31151dda-0502-4283-be18-79cf21414d30-snoop: Stopping silence generator
[Sep 11 11:36:57] DEBUG[6604]: channel.c:3194 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Sep 11 11:36:57] DEBUG[6604]: channel.c:8115 ast_channel_stop_silence_generator: Stopped silence generator on 'Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a'
[Sep 11 11:36:57] DEBUG[6604]: channel.c:5656 set_format: Channel Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a setting write format path: slin -> slin
[Sep 11 11:36:57] DEBUG[6607]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6607]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/addChannel?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30-recording&channel=out-31151dda-0502-4283-be18-79cf21414d30-snoop
[Sep 11 11:36:57] DEBUG[6607]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/addChannel] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6607]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/addChannel] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6607]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/addChannel] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6607]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/addChannel] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6607]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:513 ast_ari_invoke: Finding handler for 31151dda-0502-4283-be18-79cf21414d30-recording
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking bridgeId
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:513 ast_ari_invoke: Finding handler for addChannel
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:518 ast_ari_invoke:   Checking addChannel
[Sep 11 11:36:57] DEBUG[6607]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6607]: stasis/control.c:1295 stasis_app_control_add_channel_to_bridge: out-31151dda-0502-4283-be18-79cf21414d30-snoop: Sending channel add_to_bridge command
[Sep 11 11:36:57] DEBUG[6604]: bridge_roles.c:367 ast_channel_clear_bridge_roles: Roles did not exist on channel Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a
[Sep 11 11:36:57] DEBUG[6604]: stasis/control.c:1211 control_swap_channel_in_bridge: out-31151dda-0502-4283-be18-79cf21414d30-snoop: Adding to bridge 31151dda-0502-4283-be18-79cf21414d30-recording
[Sep 11 11:36:57] DEBUG[6604]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording' is 1 interested in APP
[Sep 11 11:36:57] DEBUG[6608]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: 0x7f33540029e8(Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a) is joining
[Sep 11 11:36:57] DEBUG[6608]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: pushing 0x7f33540029e8(Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a)
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6608]: bridge_native_rtp.c:734 native_rtp_bridge_compatible: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording' can not use native RTP bridge as two channels are required
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording is already using the new technology.
[Sep 11 11:36:57] DEBUG[6608]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: 0x7f33540029e8(Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a) is joining simple_bridge technology
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 737
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 737
[Sep 11 11:36:57] DEBUG[6604]: stasis/app.c:1442 app_subscribe_bridge: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording' is 2 interested in APP
[Sep 11 11:36:57] DEBUG[6607]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:204
[Sep 11 11:36:57] DEBUG[6607]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[6609]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:57] DEBUG[6609]: http.c:1390 handle_uri: HTTP Request URI is /ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/record?api_key=XXXXXX&app=APP&bridgeId=31151dda-0502-4283-be18-79cf21414d30-recording&format=wav&name=31151dda-0502-4283-be18-79cf21414d30
[Sep 11 11:36:57] DEBUG[6609]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/record] with handler [httpstatus] len 10
[Sep 11 11:36:57] DEBUG[6609]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/record] with handler [phoneprov] len 9
[Sep 11 11:36:57] DEBUG[6609]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/record] with handler [static] len 6
[Sep 11 11:36:57] DEBUG[6609]: http.c:1445 handle_uri: match request [ari/bridges/31151dda-0502-4283-be18-79cf21414d30-recording/record] with handler [ari] len 3
[Sep 11 11:36:57] DEBUG[6609]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:513 ast_ari_invoke: Finding handler for bridges
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:513 ast_ari_invoke: Finding handler for 31151dda-0502-4283-be18-79cf21414d30-recording
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking bridgeId
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:513 ast_ari_invoke: Finding handler for record
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking addChannel
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking removeChannel
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking videoSource
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking moh
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking play
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:518 ast_ari_invoke:   Checking record
[Sep 11 11:36:57] DEBUG[6609]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:57] DEBUG[6609]: channel.c:1001 __ast_channel_alloc_ap: Channel 0x7f334400a9c8 'Recorder/ARI-0000001a;1' allocated
[Sep 11 11:36:57] DEBUG[6609]: channel.c:1001 __ast_channel_alloc_ap: Channel 0x7f334400daf8 'Recorder/ARI-0000001a;2' allocated
[Sep 11 11:36:57] DEBUG[6609]: bridge_roles.c:274 setup_bridge_role: Set role 'recorder'
[Sep 11 11:36:57] DEBUG[6610]: bridge_channel.c:2829 bridge_channel_internal_join: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: 0x7f33440136f8(Recorder/ARI-0000001a;2) is joining
[Sep 11 11:36:57] DEBUG[6610]: bridge_channel.c:2204 bridge_channel_internal_push_full: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: pushing 0x7f33440136f8(Recorder/ARI-0000001a;2)
[Sep 11 11:36:57] DEBUG[6610]: bridge_roles.c:274 setup_bridge_role: Set role 'recorder'
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:507 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6610]: bridge_native_rtp.c:624 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording'.  Checking compatability for channels 'Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a' and 'Recorder/ARI-0000001a;2'
[Sep 11 11:36:57] DEBUG[6610]: bridge_native_rtp.c:644 native_rtp_bridge_compatible_check: Bridge '31151dda-0502-4283-be18-79cf21414d30-recording' can not use native RTP bridge as could not get details
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:517 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:507 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:526 find_best_technology: Chose bridge technology simple_bridge
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:1063 smart_bridge_operation: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording is already using the new technology.
[Sep 11 11:36:57] DEBUG[6610]: bridge.c:430 bridge_channel_complete_join: Bridge 31151dda-0502-4283-be18-79cf21414d30-recording: 0x7f33440136f8(Recorder/ARI-0000001a;2) is joining simple_bridge technology
[Sep 11 11:36:57] DEBUG[6610]: channel.c:5656 set_format: Channel Recorder/ARI-0000001a;2 setting read format path: slin -> slin
[Sep 11 11:36:57] DEBUG[6610]: channel.c:5656 set_format: Channel Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a setting write format path: slin -> slin
[Sep 11 11:36:57] DEBUG[6610]: channel.c:5656 set_format: Channel Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a setting read format path: slin -> slin
[Sep 11 11:36:57] DEBUG[6610]: channel.c:5656 set_format: Channel Recorder/ARI-0000001a;2 setting write format path: slin -> slin
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 534
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 534
[Sep 11 11:36:57] DEBUG[6608]: channel.c:4368 indicate_connected_line: Snoop/out-31151dda-0502-4283-be18-79cf21414d30-0000001a: Dropping redundant connected line update "" <>.
[Sep 11 11:36:57] DEBUG[6609]: res_stasis_recording.c:389 stasis_app_control_record: 1536665817.209: Sending record(31151dda-0502-4283-be18-79cf21414d30.wav) command
[Sep 11 11:36:57] DEBUG[6609]: media_cache.c:194 ast_media_cache_retrieve: Failed to obtain media at '/var/spool/asterisk/recording/31151dda-0502-4283-be18-79cf21414d30'
[Sep 11 11:36:57] DEBUG[6609]: media_cache.c:194 ast_media_cache_retrieve: Failed to obtain media at '/var/spool/asterisk/recording/31151dda-0502-4283-be18-79cf21414d30'
[Sep 11 11:36:57] DEBUG[6609]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:201
[Sep 11 11:36:57] DEBUG[6611]: app.c:1599 __ast_play_and_record: play_and_record: <None>, /var/spool/asterisk/recording/31151dda-0502-4283-be18-79cf21414d30, 'wav'
[Sep 11 11:36:57] DEBUG[6611]: app.c:1623 __ast_play_and_record: Recording Formats: sfmts=wav
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:1457 __ast_websocket_write_string: Writing websocket string of length 250
[Sep 11 11:36:57] DEBUG[22287]: res_http_websocket.c:358 __ast_websocket_write: Writing websocket text frame, length 250
[Sep 11 11:36:57] DEBUG[6609]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:57] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:57] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:58] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:58] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000002d to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:58] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.16' into...
[Sep 11 11:36:58] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.16' and port ''.
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:208 ip_identify_match_check: Source address 192.168.0.16:5060 does not match identify 'in'
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.16:5060 matches identify 'agents'
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'agents' SIP message matched to endpoint agents
[Sep 11 11:36:58] DEBUG[16550]: res_pjsip/pjsip_distributor.c:393 find_dialog: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:58] DEBUG[16550]: res_pjsip/pjsip_distributor.c:471 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000001c to use for Request msg OPTIONS/cseq=10 (rdata0x7f335000cef8)
[Sep 11 11:36:58] DEBUG[22397]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.0.17' into...
[Sep 11 11:36:58] DEBUG[22397]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.0.17' and port ''.
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:203 ip_identify_match_check: Source address 192.168.0.17:5060 matches identify 'in'
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip_endpoint_identifier_ip.c:236 common_identify: Identify 'in' SIP message matched to endpoint in
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target '192.168.0.17'
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target '192.168.0.17' is 'UDP'
[Sep 11 11:36:58] DEBUG[22397]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target '192.168.0.17' is an IP address, skipping resolution
[Sep 11 11:36:59] DEBUG[6617]: http.c:1914 httpd_helper_thread: HTTP opening session.  Top level
[Sep 11 11:36:59] DEBUG[6617]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels?api_key=XXXXXX&app=APP
[Sep 11 11:36:59] DEBUG[6617]: http.c:1445 handle_uri: match request [ari/channels] with handler [httpstatus] len 10
[Sep 11 11:36:59] DEBUG[6617]: http.c:1445 handle_uri: match request [ari/channels] with handler [phoneprov] len 9
[Sep 11 11:36:59] DEBUG[6617]: http.c:1445 handle_uri: match request [ari/channels] with handler [static] len 6
[Sep 11 11:36:59] DEBUG[6617]: http.c:1445 handle_uri: match request [ari/channels] with handler [ari] len 3
[Sep 11 11:36:59] DEBUG[6617]: http.c:1461 handle_uri: Match made with [ari]
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:513 ast_ari_invoke: Finding handler for channels
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking asterisk
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking playbacks
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking sounds
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking deviceStates
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking applications
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking endpoints
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking bridges
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:518 ast_ari_invoke:   Checking channels
[Sep 11 11:36:59] DEBUG[6617]: res_ari.c:538 ast_ari_invoke:   Got it!
[Sep 11 11:36:59] DEBUG[6617]: http.c:551 ast_http_send: HTTP keeping session open.  status_code:200
[Sep 11 11:36:59] DEBUG[6617]: http.c:1971 httpd_helper_thread: HTTP closing session.  Top level