Connected to Asterisk 11.25.1 currently running on asterisk11 (pid = 4807)
asterisk11*CLI> core set verbose 9
Console verbose was OFF and is now 9.
asterisk11*CLI> core set debug 9
Core debug was OFF and is now 9.
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 315d56be487327a1 (Checking From) --From tag 5eb240746dc34b19 --To-tag
[Aug  3 08:47:57] DEBUG[5319]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:3888 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.67:5060
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:49980' into...
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '49980'.
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:8660 sip_alloc: Allocating new SIP dialog for 315d56be487327a1 - INVITE (No RTP)
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:28533 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:49980' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '49980'.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 315d56be487327a1 (Checking From) --From tag 5eb240746dc34b19 --To-tag as0b908e6c
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:28533 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '315d56be487327a1' of Response 14413: Match Found
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 315d56be487327a1 (Checking From) --From tag 5eb240746dc34b19 --To-tag
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  3 08:47:57] DEBUG[5319]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:28533 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:49980' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '49980'.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f02f0020238'
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:2565 ast_rtp_new: Allocated port 40720 for RTP instance '0x7f02f0020238'
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7f02f0020238' is setup and ready to go
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4699 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f02f0020238'
  == Using SIP RTP CoS mark 5
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP o=- 1803759786 1935627408 IN IP4 192.168.1.49... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP a=tool:baresip 0.4.6... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f0296eafc30
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f0296eafc30
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f0296eafc30
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP b=AS:125... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=label:1... UNSUPPORTED OR FAILED.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f02f0020238'
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f0296eafc30 to 0x7f02f0020400
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f0296eafc30 to 0x7f02f0020400
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f0296eafc30 to 0x7f02f0020400
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4665 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f02f0020238'
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:10695 process_sdp: We're settling with these formats: (ulaw|alaw)
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:25855 handle_request_invite: Checking SIP call limits for device 0x1f9c180
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:6564 update_call_counter: Updating call counter for incoming call
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:7829 sip_new: *** Our native formats are (ulaw)
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:7830 sip_new: *** Joint capabilities are (ulaw|alaw)
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:7831 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw)
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:7832 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:7865 sip_new: This channel will not be able to handle video.
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:16423 build_route: build_route: Contact hop: <sip:0x222c180@192.168.1.49:49980>
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:26092 handle_request_invite: SIP/7777-00000002: New call is still down.... Trying...
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  3 08:47:57] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1'
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp'
    -- Executing [8888@buh:1] NoOp("SIP/7777-00000002", "") in new stack
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: pbx.c:3778 ast_str_retrieve_variable: Result of 'EXTEN' is '8888'
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'Dial'
    -- Executing [8888@buh:2] Dial("SIP/7777-00000002", "SIP/8888,20,tirU(subAnswer)") in new stack
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:30087 sip_request_call: Asked to create a SIP channel with formats: (ulaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:8660 sip_alloc: Allocating new SIP dialog for 0d376406506c54a767d02f6d34323bce@[fe80::a00:27ff:fe70:9b1b]:5060 - INVITE (No RTP)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f02880107e8'
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:2565 ast_rtp_new: Allocated port 40906 for RTP instance '0x7f02880107e8'
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7f02880107e8' is setup and ready to go
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:4699 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f02880107e8'
  == Using SIP RTP CoS mark 5
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'.
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:3888 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.67:5060
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:7778' into...
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '7778'.
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:8446 change_callid_pvt: SIP call-id changed from '0d376406506c54a767d02f6d34323bce@[fe80::a00:27ff:fe70:9b1b]:5060' to '2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060'
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7829 sip_new: *** Our native formats are (ulaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7830 sip_new: *** Joint capabilities are (ulaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7831 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7832 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7834 sip_new: *** Our preferred formats from the incoming channel are (ulaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:7865 sip_new: This channel will not be able to handle video.
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: channel_internal_api.c:882 ast_channel_callid_set: Channel Call ID changing from [C-00000001] to [C-00000001]
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:6260 sip_call: Outgoing Call for 8888
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:6564 update_call_counter: Updating call counter for outgoing call
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:13086 add_sdp: This call needs video offers, but there's no video support enabled!
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:13134 add_sdp: ** Our capability: (gsm|ulaw|alaw|h263|testlaw) Video flag: False Text flag: False
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:13135 add_sdp: ** Our prefcodec: (ulaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:13271 add_sdp: -- Done with adding codecs to SDP
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:13471 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|alaw|h263|testlaw)
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:3374 initialize_initreq: Initializing initreq for method INVITE - callid 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.49:7778
    -- Called SIP/8888
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:57] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  3 08:47:57] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060 (Checking To) --From tag as55dfe3fe --To-tag bc52a109
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:4470 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060' Request 102: Found
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:22858 handle_response_invite: SIP response 180 to standard invite
[Aug  3 08:47:57] DEBUG[5319][C-00000001]: chan_sip.c:16423 build_route: build_route: Contact hop: <sip:8888@192.168.1.49:7778;rinstance=ee87a096260f39a7>
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  3 08:47:57] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  3 08:47:57] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1'
[Aug  3 08:47:57] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/8888' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
    -- SIP/8888-00000003 is ringing
[Aug  3 08:47:57] DEBUG[7744][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:58] DEBUG[5318]: res_timing_timerfd.c:226 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 2 instead
[Aug  3 08:47:58] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060 (Checking To) --From tag as55dfe3fe --To-tag bc52a109
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:4391 __sip_ack: Acked pending invite 102
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060' of Request 102: Match Found
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:22858 handle_response_invite: SIP response 200 to standard invite
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP o=3cxVCE 342586095 78674685 IN IP4 192.168.1.49... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into...
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:9959 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f0296eaee30
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x7f0296eaee30
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f0296eaee30
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f0296eaee30
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f02880107e8'
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f0296eaee30 to 0x7f02880109b0
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x7f0296eaee30 to 0x7f02880109b0
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f0296eaee30 to 0x7f02880109b0
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f0296eaee30 to 0x7f02880109b0
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4665 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f02880107e8'
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10695 process_sdp: We're settling with these formats: (gsm|ulaw|alaw)
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:10702 process_sdp: We have an owner, now see if we need to change this call
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:6564 update_call_counter: Updating call counter for outgoing call
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:16423 build_route: build_route: Contact hop: <sip:8888@192.168.1.49:7778;rinstance=ee87a096260f39a7>
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:7778' into...
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '7778'.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:7778' into...
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '7778'.
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'ACK sip:888' onto UDP socket destined for 192.168.1.49:7778
    -- SIP/8888-00000003 answered SIP/7777-00000002
    -- SIP/8888-00000003 Internal Gosub(subAnswer,s,1) start
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: app_stack.c:974 gosub_run: SIP/8888-00000003 Original location: ato,,1
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: app_stack.c:579 gosub_exec: Channel SIP/8888-00000003 has no datastore, so we're allocating one.
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: app_stack.c:978 gosub_run: Gosub exited with status 0
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@subAnswer:1] NoOp("SIP/8888-00000003", "") in new stack
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(userfield) result is '(null)'
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '8888'
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'Set'
    -- Executing [s@subAnswer:2] Set("SIP/8888-00000003", "CDR(userfield)=:8888") in new stack
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(cstfld) result is '(null)'
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '8888'
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'Set'
    -- Executing [s@subAnswer:3] Set("SIP/8888-00000003", "CDR(cstfld)=:8888") in new stack
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'Return'
    -- Executing [s@subAnswer:4] Return("SIP/8888-00000003", "") in new stack
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: app_stack.c:1040 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  3 08:47:58] DEBUG[7744][C-00000001]: app_stack.c:1066 gosub_run: SIP/8888-00000003 Ending location: ato,,1
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  3 08:47:58] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1'
[Aug  3 08:47:58] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/8888' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:7147 sip_answer: SIP answering channel: SIP/7777-00000002
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:13585 transmit_response_with_sdp: Setting framing from config on incoming call
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:13134 add_sdp: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:13135 add_sdp: ** Our prefcodec: (nothing)
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:13271 add_sdp: -- Done with adding codecs to SDP
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:13471 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw)
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: features.c:4433 ast_bridge_call: bridge answer set, chan answer set
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: features.c:4254 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/8888-00000003 since we're bridging
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  3 08:47:58] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  3 08:47:58] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1'
[Aug  3 08:47:58] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  3 08:47:58] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 315d56be487327a1 (Checking From) --From tag 5eb240746dc34b19 --To-tag as224a759b
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:28533 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Aug  3 08:47:58] DEBUG[5319][C-00000001]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '315d56be487327a1' of Response 14414: Match Found
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:4333 ast_rtp_read: 0x7f0288015dd0 -- Probation learning mode pass with source address 192.168.1.49:40024
       > 0x7f0288015dd0 -- Probation passed - setting RTP source address to 192.168.1.49:40024
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:3446 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:3481 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:3343 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f02f0020238'
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:4333 ast_rtp_read: 0x7f02f0025820 -- Probation learning mode pass with source address 192.168.1.49:14578
       > 0x7f02f0025820 -- Probation passed - setting RTP source address to 192.168.1.49:14578
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:3446 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Aug  3 08:47:58] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:3481 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160
[Aug  3 08:47:59] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060 (Checking From) --From tag bc52a109 --To-tag as55dfe3fe
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: chan_sip.c:28533 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:7778' into...
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '7778'.
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: chan_sip.c:3387 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f02880107e8'
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: chan_sip.c:27149 handle_request_bye: Received bye, issuing owner hangup
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:7778
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:7650 ast_generic_bridge: Didn't get a frame from channel: SIP/8888-00000003
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:8144 ast_channel_bridge: Bridge stops bridging channels SIP/7777-00000002 and SIP/8888-00000003
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:2662 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/7777-00000002'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp'
    -- Executing [h@buh:1] NoOp("SIP/7777-00000002", "") in new stack
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: cdr_radius.c:216 radius_log: Unable to create RADIUS record. CDR not recorded!
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x2da9838) called (obj->txf = (nil))
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: res_config_sqlite.c:836 cdr_handler: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid,userfield) VALUES ('"ExtUser" <7777>','7777','8888','buh','SIP/7777-00000002','SIP/8888-00000003','Dial','SIP/8888,20,tirU(subAnswer)','2017-08-03 08:47:57','2017-08-03 08:47:58','2017-08-03 08:47:59','2','1','ANSWERED','DOCUMENTATION','1501739277.2',':8888')
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:2841 ast_hangup: Hanging up channel 'SIP/8888-00000003'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: chan_sip.c:6929 sip_hangup: Hangup call SIP/8888-00000003, SIP callid 2e88d37e14827c660b4aaa7a34007c82@192.168.1.67:5060
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f02880107e8'
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888
[Aug  3 08:47:59] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use)
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1'
[Aug  3 08:47:59] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/8888' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: app_dial.c:3120 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: pbx.c:6789 __ast_pbx_run: Spawn extension (buh,8888,2) exited non-zero on 'SIP/7777-00000002'
  == Spawn extension (buh, 8888, 2) exited non-zero on 'SIP/7777-00000002'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:2662 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/7777-00000002'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: channel.c:2841 ast_hangup: Hanging up channel 'SIP/7777-00000002'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: chan_sip.c:6929 sip_hangup: Hangup call SIP/7777-00000002, SIP callid 315d56be487327a1
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f02f0020238'
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:49980' into...
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '49980'.
[Aug  3 08:47:59] DEBUG[7744][C-00000001]: chan_sip.c:3731 __sip_xmit: Trying to put 'BYE sip:0x2' onto UDP socket destined for 192.168.1.49:49980
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777
[Aug  3 08:47:59] DEBUG[5293]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use)
[Aug  3 08:47:59] DEBUG[5293]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1'
[Aug  3 08:47:59] DEBUG[5329]: app_queue.c:1924 handle_statechange: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug  3 08:47:59] DEBUG[5319]: chan_sip.c:9057 find_call: = Looking for  Call ID: 315d56be487327a1 (Checking To) --From tag as224a759b --To-tag 5eb240746dc34b19
[Aug  3 08:47:59] DEBUG[5319][C-00000001]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '315d56be487327a1' of Request 102: Match Found
[Aug  3 08:47:59] DEBUG[5319]: chan_sip.c:6379 sip_pvt_dtor: Destroying SIP dialog 315d56be487327a1
[Aug  3 08:47:59] DEBUG[5319]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x7f02f0020238'
asterisk11*CLI> exit