Connected to Asterisk 13.17.0 currently running on asterisk13 (pid = 1397)
asterisk13*CLI> core set verbose 9
Console verbose was OFF and is now 9.
asterisk13*CLI> core set debug 9
Core debug was OFF and is now 9.
[Aug  9 13:53:20] DEBUG[1470]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Aug  9 13:53:20] DEBUG[1400]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 26
[Aug  9 13:53:20] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:20] DEBUG[1430]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  9 13:53:20] DEBUG[1430]: chan_sip.c:3911 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.67:5060
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:20] DEBUG[1430]: chan_sip.c:9016 __sip_alloc: Allocating new SIP dialog for 5db043fd2f5c2c59 - INVITE (No RTP)
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:20] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag as3a2d9253
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '5db043fd2f5c2c59' of Response 14522: Match Found
[Aug  9 13:53:20] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:20] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff74c00de60'
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 12046 for RTP instance '0x7ff74c00de60'
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session 0.0.0.0:12046 (12046) for RTP instance '0x7ff74c00de60'
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff74c00de60' is setup and ready to go
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'asterisk13.test' into...
[Aug  9 13:53:20] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'asterisk13.test' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: acl.c:795 resolve_first: Multiple addresses. Using the first only
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff74c00de60'
  == Using SIP RTP CoS mark 5
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP o=- 1946747261 1580937075 IN IP4 192.168.1.49... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into...
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP a=tool:baresip 0.4.6... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff74bf80b40
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7ff74bf80b40
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7ff74bf80b40
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP b=AS:125... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=label:1... UNSUPPORTED OR FAILED.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff74c00de60'
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff74c0095c8) from 0x7ff74bf80b40 to 0x7ff74c00e028
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff74c0158a8) from 0x7ff74bf80b40 to 0x7ff74c00e028
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff74c015d28) from 0x7ff74bf80b40 to 0x7ff74c00e028
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff74c00de60'
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:11097 process_sdp: We're settling with these formats: (ulaw|alaw)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:26354 handle_request_invite: Checking SIP call limits for device 0x229c580
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:6768 update_call_counter: Updating call counter for incoming call
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff74c0103c0 'SIP/7777-00000002' allocated
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:8165 sip_new: *** Our native formats are (ulaw)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:8166 sip_new: *** Joint capabilities are (ulaw|alaw)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:8167 sip_new: *** Our capabilities are (ulaw|alaw|gsm|h263)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:8168 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:8201 sip_new: This channel will not be able to handle video.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:26558 handle_request_invite: SIP/7777-00000002: New call is still down.... Trying...
[Aug  9 13:53:30] DEBUG[1400]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:30] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28795 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 14523, ours 14523)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:30] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28795 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 14523, ours 14523)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:30] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28795 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 14523, ours 14523)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:30] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:30] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:28795 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 14523, ours 14523)
[Aug  9 13:53:30] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:30] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  9 13:53:30] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777
[Aug  9 13:53:30] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp'
    -- Executing [8888@buh:1] NoOp("SIP/7777-00000002", "") in new stack
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(userfield) result is ''
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'Set'
    -- Executing [8888@buh:2] Set("SIP/7777-00000002", "CDR(userfield)=:buh") in new stack
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '8888'
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'Dial'
    -- Executing [8888@buh:3] Dial("SIP/7777-00000002", "SIP/8888,20,tirU(subAnswer)") in new stack
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:30413 sip_request_call: Asked to create a SIP channel with formats: (ulaw)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:9016 __sip_alloc: Allocating new SIP dialog for 4a0f421f161e0d382dafddb46b6965f7@[fe80::a00:27ff:fede:24f1]:5060 - INVITE (No RTP)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff73000caa0'
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 10926 for RTP instance '0x7ff73000caa0'
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session 0.0.0.0:10926 (10926) for RTP instance '0x7ff73000caa0'
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff73000caa0' is setup and ready to go
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'asterisk13.test' into...
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'asterisk13.test' and port ''.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: acl.c:795 resolve_first: Multiple addresses. Using the first only
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff73000caa0'
  == Using SIP RTP CoS mark 5
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:3911 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.67:5060
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into...
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8801 change_callid_pvt: SIP call-id changed from '4a0f421f161e0d382dafddb46b6965f7@[fe80::a00:27ff:fede:24f1]:5060' to '285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060'
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff730001e50 'SIP/8888-00000003' allocated
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8165 sip_new: *** Our native formats are (ulaw)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8166 sip_new: *** Joint capabilities are (ulaw)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8167 sip_new: *** Our capabilities are (ulaw|alaw|gsm|h263)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8168 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8170 sip_new: *** Our preferred formats from the incoming channel are (ulaw)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:8201 sip_new: This channel will not be able to handle video.
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: channel_internal_api.c:935 ast_channel_callid_set: Channel Call ID changing from [C-00000001] to [C-00000001]
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:6474 sip_call: Outgoing Call for 8888
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:6768 update_call_counter: Updating call counter for outgoing call
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:13487 add_sdp: This call needs video offers, but there's no video support enabled!
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw|gsm|h263) Video flag: False Text flag: False
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (ulaw)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:13680 add_sdp: -- Done with adding codecs to SDP
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:13899 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|gsm|h263)
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:3397 initialize_initreq: Initializing initreq for method INVITE - callid 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.49:6640
    -- Called SIP/8888
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: channel.c:4560 indicate_connected_line: SIP/7777-00000002: Dropping redundant connected line update "OneUser" <8888>.
[Aug  9 13:53:31] DEBUG[1400]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1
[Aug  9 13:53:31] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060 (Checking To) --From tag as0e2ef50d --To-tag 344fe83b
[Aug  9 13:53:31] DEBUG[1430][C-00000001]: chan_sip.c:4579 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060' Request 102: Found
[Aug  9 13:53:31] DEBUG[1430][C-00000001]: chan_sip.c:23613 handle_response_invite: SIP response 180 to standard invite
    -- SIP/8888-00000003 is ringing
[Aug  9 13:53:31] DEBUG[1474][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:31] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  9 13:53:31] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888
[Aug  9 13:53:31] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 04cf770a31df6da8 (Checking From) --From tag 5aa53b3462781251 --To-tag
[Aug  9 13:53:32] DEBUG[1430]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:3911 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.67:5060
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:9016 __sip_alloc: Allocating new SIP dialog for 04cf770a31df6da8 - REGISTER (No RTP)
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:28770 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 04cf770a31df6da8 (Checking From) --From tag 5aa53b3462781251 --To-tag
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:28770 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  9 13:53:32] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:16905 parse_register_contact: Store REGISTER's src-IP:port for call routing.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:17069 build_path: build_path: do not use Path headers
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  9 13:53:32] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:4362 __sip_autodestruct: Auto destroying SIP dialog 'MTJiM2IyZmYxZTM0Y2ZlZjNkNGZhMDM2MTMwOTIzZjQ.'
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:6590 sip_pvt_dtor: Destroying SIP dialog MTJiM2IyZmYxZTM0Y2ZlZjNkNGZhMDM2MTMwOTIzZjQ.
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060 (Checking To) --From tag as0e2ef50d --To-tag 344fe83b
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:4522 __sip_ack: Acked pending invite 102
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060' of Request 102: Match Found
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:23613 handle_response_invite: SIP response 200 to standard invite
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP o=3cxVCE 311661870 9147645 IN IP4 192.168.1.49... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into...
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10339 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff74bf7fae0
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7ff74bf7fae0
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7ff74bf7fae0
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7ff74bf7fae0
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:937 ast_rtp_ice_set_role: Set role to CONTROLLING (0x7ff73000caa0)
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:940 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7ff73000caa0)
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff73000caa0'
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff74c003bc8) from 0x7ff74bf7fae0 to 0x7ff73000cc68
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7ff74c00ffb8) from 0x7ff74bf7fae0 to 0x7ff73000cc68
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff74c00fb38) from 0x7ff74bf7fae0 to 0x7ff73000cc68
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff74c0141a8) from 0x7ff74bf7fae0 to 0x7ff73000cc68
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff73000caa0'
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:11097 process_sdp: We're settling with these formats: (ulaw|alaw|gsm)
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:11104 process_sdp: We have an owner, now see if we need to change this call
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:6768 update_call_counter: Updating call counter for outgoing call
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into...
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into...
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'.
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'ACK sip:888' onto UDP socket destined for 192.168.1.49:6640
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: channel.c:4560 indicate_connected_line: SIP/7777-00000002: Dropping redundant connected line update "OneUser" <8888>.
    -- SIP/8888-00000003 answered SIP/7777-00000002
    -- SIP/8888-00000003 Internal Gosub(subAnswer,s,1) start
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: app_stack.c:1006 gosub_run: SIP/8888-00000003 Original location: ato,,1
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: app_stack.c:606 gosub_exec: Channel SIP/8888-00000003 has no datastore, so we're allocating one.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: app_stack.c:1010 gosub_run: Gosub exited with status 0
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@subAnswer:1] NoOp("SIP/8888-00000003", "") in new stack
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  9 13:53:32] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(userfield) result is ''
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'Set'
    -- Executing [s@subAnswer:2] Set("SIP/8888-00000003", "CDR(userfield)=:subAnswer") in new stack
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(userfield) result is ':subAnswer'
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'Set'
    -- Executing [s@subAnswer:3] Set("SIP/8888-00000003", "CDR(userfield)=:subAnswer:moreData") in new stack
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: pbx.c:2875 pbx_extension_helper: Launching 'Return'
    -- Executing [s@subAnswer:4] Return("SIP/8888-00000003", "") in new stack
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: app_stack.c:1068 gosub_run: Spawn extension (ato,,1) exited with -1 on 'SIP/8888-00000003'
  == Spawn extension (ato, , 1) exited non-zero on 'SIP/8888-00000003'
    -- SIP/8888-00000003 Internal Gosub(subAnswer,s,1) complete GOSUB_RETVAL=
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: app_stack.c:1094 gosub_run: SIP/8888-00000003 Ending location: ato,,1
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:7413 sip_answer: SIP answering channel: SIP/7777-00000002
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3430 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (nothing)
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:13680 add_sdp: -- Done with adding codecs to SDP
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:13705 add_sdp: Setting framing on incoming call: 0
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:13899 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw)
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:502 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge '2871cecb-ef8f-46a0-805c-f6064b0fc382' can not use native RTP bridge as two channels are required
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:795 bridge_base_init: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: calling simple_bridge technology constructor
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:803 bridge_base_init: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: calling simple_bridge technology start
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  9 13:53:32] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777
[Aug  9 13:53:32] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730021da0(SIP/8888-00000003) is joining
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: pushing 0x7ff730021da0(SIP/8888-00000003)
    -- Channel SIP/8888-00000003 joined 'simple_bridge' basic-bridge <2871cecb-ef8f-46a0-805c-f6064b0fc382>
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge '2871cecb-ef8f-46a0-805c-f6064b0fc382' can not use native RTP bridge as two channels are required
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:1047 smart_bridge_operation: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382 is already using the new technology.
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: bridge.c:432 bridge_channel_complete_join: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730021da0(SIP/8888-00000003) is joining simple_bridge technology
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: res_rtp_asterisk.c:3444 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730000d10(SIP/7777-00000002) is joining
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: pushing 0x7ff730000d10(SIP/7777-00000002)
    -- Channel SIP/7777-00000002 joined 'simple_bridge' basic-bridge <2871cecb-ef8f-46a0-805c-f6064b0fc382>
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge_native_rtp.c:617 native_rtp_bridge_compatible_check: Bridge '2871cecb-ef8f-46a0-805c-f6064b0fc382'.  Checking compatability for channels 'SIP/8888-00000003' and 'SIP/7777-00000002'
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge_native_rtp.c:651 native_rtp_bridge_compatible_check: Bridge '2871cecb-ef8f-46a0-805c-f6064b0fc382' can not use native RTP bridge as channel 'SIP/8888-00000003' has DTMF hooks
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:1047 smart_bridge_operation: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382 is already using the new technology.
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: bridge.c:432 bridge_channel_complete_join: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730000d10(SIP/7777-00000002) is joining simple_bridge technology
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3444 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet
[Aug  9 13:53:32] DEBUG[1412]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/8888-00000003 - start 1502276011.010419 answer 1502276012.723005 end 1502276012.732610 dispo ANSWERED
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7ff73000d5a0 -- Probation learning mode pass with source address 192.168.1.49:40024
       > 0x7ff73000d5a0 -- Probation passed - setting RTP source address to 192.168.1.49:40024
[Aug  9 13:53:32] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking From) --From tag 09e119314c8038d2 --To-tag as39c82c12
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Aug  9 13:53:32] DEBUG[1430][C-00000001]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '5db043fd2f5c2c59' of Response 14523: Match Found
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:4017 ast_rtp_write: Ooh, format changed from none to ulaw
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3860 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7ff74c00de60'
[Aug  9 13:53:32] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7ff74c024bf0 -- Probation learning mode pass with source address 192.168.1.49:16064
       > 0x7ff74c024bf0 -- Probation passed - setting RTP source address to 192.168.1.49:16064
[Aug  9 13:53:32] DEBUG[1476][C-00000001]: res_rtp_asterisk.c:4017 ast_rtp_write: Ooh, format changed from none to ulaw
[Aug  9 13:53:33] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060 (Checking From) --From tag 344fe83b --To-tag as0e2ef50d
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: chan_sip.c:28770 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into...
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'.
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: chan_sip.c:3410 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: chan_sip.c:27377 handle_request_bye: Received bye, issuing owner hangup
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:6640
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff730021da0(SIP/8888-00000003) state from:0 to:1
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: pulling 0x7ff730021da0(SIP/8888-00000003)
    -- Channel SIP/8888-00000003 left 'simple_bridge' basic-bridge <2871cecb-ef8f-46a0-805c-f6064b0fc382>
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730021da0(SIP/8888-00000003) is leaving simple_bridge technology
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge.c:322 bridge_dissolve: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: dissolving bridge with cause 16(Normal Clearing)
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff730000d10(SIP/7777-00000002) state from:0 to:2
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge.c:283 bridge_queue_action_nodup: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: queueing action type:13 sub:1001
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: bridge.c:1004 smart_bridge_operation: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382 is dissolved, not performing smart bridge operation.
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: channel.c:2681 ast_hangup: Channel 0x7ff730001e50 'SIP/8888-00000003' hanging up.  Refs: 2
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: chan_sip.c:7155 sip_hangup: Hangup call SIP/8888-00000003, SIP callid 285ef54679e61af41c4b3d623a07ad64@192.168.1.67:5060
[Aug  9 13:53:33] DEBUG[1476][C-00000001]: channel.c:2233 ast_channel_destructor: Channel 0x7ff730001e50 'SIP/8888-00000003' destroying
[Aug  9 13:53:33] DEBUG[1412]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/7777-00000002 - start 1502276010.996499 answer 1502276012.728016 end 1502276013.624514 dispo ANSWERED
[Aug  9 13:53:33] DEBUG[1412]: cdr.c:1121 cdr_object_create_public_records: CDR for SIP/8888-00000003 is dialed and has no Party B; discarding
[Aug  9 13:53:33] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  9 13:53:33] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888
[Aug  9 13:53:33] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: pulling 0x7ff730000d10(SIP/7777-00000002)
    -- Channel SIP/7777-00000002 left 'simple_bridge' basic-bridge <2871cecb-ef8f-46a0-805c-f6064b0fc382>
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: 0x7ff730000d10(SIP/7777-00000002) is leaving simple_bridge technology
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge.c:1004 smart_bridge_operation: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382 is dissolved, not performing smart bridge operation.
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: res_rtp_asterisk.c:3451 ast_rtp_change_source: Changing ssrc from 1370178576 to 364670894 due to a source change
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge.c:649 destroy_bridge: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: actually destroying basic bridge, nobody wants it anymore
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge.c:674 destroy_bridge: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: calling basic bridge destructor
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge.c:680 destroy_bridge: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: calling simple_bridge technology stop
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: bridge.c:687 destroy_bridge: Bridge 2871cecb-ef8f-46a0-805c-f6064b0fc382: calling simple_bridge technology destructor
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: app_dial.c:3233 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: pbx.c:4347 __ast_pbx_run: Spawn extension (buh,8888,3) exited non-zero on 'SIP/7777-00000002'
  == Spawn extension (buh, 8888, 3) exited non-zero on 'SIP/7777-00000002'
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: channel.c:2590 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/7777-00000002'
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: channel.c:2681 ast_hangup: Channel 0x7ff74c0103c0 'SIP/7777-00000002' hanging up.  Refs: 2
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: chan_sip.c:7155 sip_hangup: Hangup call SIP/7777-00000002, SIP callid 5db043fd2f5c2c59
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into...
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'.
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: chan_sip.c:3754 __sip_xmit: Trying to put 'BYE sip:0x2' onto UDP socket destined for 192.168.1.49:4527
[Aug  9 13:53:33] DEBUG[1474][C-00000001]: channel.c:2233 ast_channel_destructor: Channel 0x7ff74c0103c0 'SIP/7777-00000002' destroying
[Aug  9 13:53:33] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  9 13:53:33] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777
[Aug  9 13:53:33] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  9 13:53:33] DEBUG[1412]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x30ad7c0 from class 'asteriskdb'
[Aug  9 13:53:33] DEBUG[1412]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,userfield,uniqueid,linkedid,sequence) VALUES ({ ts '2017-08-09 13:53:30' },'"ExtUser" <7777>','7777','8888','buh','SIP/7777-00000002','SIP/8888-00000003','Dial','SIP/8888,20,tirU(subAnswer)',2,0,'ANSWERED',3,':buh;:subAnswer:moreData','1502276010.3','1502276010.3','2')]
[Aug  9 13:53:33] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for  Call ID: 5db043fd2f5c2c59 (Checking To) --From tag as39c82c12 --To-tag 09e119314c8038d2
[Aug  9 13:53:33] DEBUG[1430][C-00000001]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '5db043fd2f5c2c59' of Request 102: Match Found
[Aug  9 13:53:33] DEBUG[1430]: chan_sip.c:6590 sip_pvt_dtor: Destroying SIP dialog 5db043fd2f5c2c59
[Aug  9 13:53:33] DEBUG[1430]: rtp_engine.c:402 instance_destructor: Destroyed RTP instance '0x7ff74c00de60'
[Aug  9 13:53:33] DEBUG[1412]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x30ad7c0 into pool
asterisk13*CLI> exit
Asterisk cleanly ending (0).
Executing last minute cleanups