Core debug was OFF and is now 9. [Aug 1 15:12:02] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0099310a187b33ff (Checking From) --From tag 4b500b5f57e06d39 --To-tag [Aug 1 15:12:02] DEBUG[7370]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 1 15:12:02] DEBUG[7370]: chan_sip.c:3888 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.67:5060 [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52101' into... [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52101'. [Aug 1 15:12:02] DEBUG[7370]: chan_sip.c:8660 sip_alloc: Allocating new SIP dialog for 0099310a187b33ff - INVITE (No RTP) [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:28533 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52101' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52101'. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:02] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0099310a187b33ff (Checking From) --From tag 4b500b5f57e06d39 --To-tag as0d12e16c [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:28533 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '0099310a187b33ff' of Response 32162: Match Found [Aug 1 15:12:02] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0099310a187b33ff (Checking From) --From tag 4b500b5f57e06d39 --To-tag [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 1 15:12:02] DEBUG[7370]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:28533 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52101' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52101'. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f28b4013278' [Aug 1 15:12:02] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:2565 ast_rtp_new: Allocated port 40038 for RTP instance '0x7f28b4013278' [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7f28b4013278' is setup and ready to go [Aug 1 15:12:02] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4699 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f28b4013278' [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP o=- 192417290 211631727 IN IP4 192.168.1.49... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP a=tool:baresip 0.4.6... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f28619f3c30 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f28619f3c30 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f28619f3c30 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP b=AS:125... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=label:1... UNSUPPORTED OR FAILED. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f28b4013278' [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f28619f3c30 to 0x7f28b4013440 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f28619f3c30 to 0x7f28b4013440 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f28619f3c30 to 0x7f28b4013440 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4665 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f28b4013278' [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:10695 process_sdp: We're settling with these formats: (ulaw|alaw) [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:25855 handle_request_invite: Checking SIP call limits for device 0x1f9c180 [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:6564 update_call_counter: Updating call counter for incoming call [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:7829 sip_new: *** Our native formats are (ulaw) [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:7830 sip_new: *** Joint capabilities are (ulaw|alaw) [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:7831 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:7832 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:7865 sip_new: This channel will not be able to handle video. [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:16423 build_route: build_route: Contact hop: [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:26092 handle_request_invite: SIP/7777-00000000: New call is still down.... Trying... [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 1 15:12:02] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp' [Aug 1 15:12:02] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777 [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: pbx.c:3778 ast_str_retrieve_variable: Result of 'EXTEN' is '8888' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'Dial' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:30087 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:8660 sip_alloc: Allocating new SIP dialog for 7c2151bb4e11c6b7768cb2760fe9b662@[fe80::a00:27ff:fe70:9b1b]:5060 - INVITE (No RTP) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f28b0010798' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:2565 ast_rtp_new: Allocated port 40968 for RTP instance '0x7f28b0010798' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7f28b0010798' is setup and ready to go [Aug 1 15:12:02] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:4699 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f28b0010798' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off [Aug 1 15:12:02] DEBUG[7864][C-00000000]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:3888 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.67:5060 [Aug 1 15:12:02] DEBUG[7864][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52104' into... [Aug 1 15:12:02] DEBUG[7864][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52104'. [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:5604 do_setnat: Setting NAT on RTP to Off [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:8446 change_callid_pvt: SIP call-id changed from '7c2151bb4e11c6b7768cb2760fe9b662@[fe80::a00:27ff:fe70:9b1b]:5060' to '0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060' [Aug 1 15:12:02] DEBUG[7864][C-00000000]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7829 sip_new: *** Our native formats are (ulaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7830 sip_new: *** Joint capabilities are (ulaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7831 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7832 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7834 sip_new: *** Our preferred formats from the incoming channel are (ulaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:7865 sip_new: This channel will not be able to handle video. [Aug 1 15:12:02] DEBUG[7864][C-00000000]: channel_internal_api.c:882 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:6260 sip_call: Outgoing Call for 8888 [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:6564 update_call_counter: Updating call counter for outgoing call [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:13086 add_sdp: This call needs video offers, but there's no video support enabled! [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:13134 add_sdp: ** Our capability: (gsm|ulaw|alaw|h263|testlaw) Video flag: False Text flag: False [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:13135 add_sdp: ** Our prefcodec: (ulaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:13271 add_sdp: -- Done with adding codecs to SDP [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:13471 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|alaw|h263|testlaw) [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:3374 initialize_initreq: Initializing initreq for method INVITE - callid 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.49:52104 [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:02] DEBUG[7380]: 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 1 15:12:02] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 (Checking To) --From tag as7ff1e0e7 --To-tag 2776247a [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:4470 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060' Request 102: Found [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:22858 handle_response_invite: SIP response 180 to standard invite [Aug 1 15:12:02] DEBUG[7370][C-00000000]: chan_sip.c:16423 build_route: build_route: Contact hop: [Aug 1 15:12:02] DEBUG[7864][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 1 15:12:02] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888 [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 1 15:12:02] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1' [Aug 1 15:12:02] DEBUG[7380]: 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 1 15:12:04] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 (Checking To) --From tag as7ff1e0e7 --To-tag 2776247a [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:4391 __sip_ack: Acked pending invite 102 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060' of Request 102: Match Found [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:22858 handle_response_invite: SIP response 200 to standard invite [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP o=3cxVCE 331191660 98784690 IN IP4 192.168.1.49... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into... [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:9959 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f28619f2e30 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x7f28619f2e30 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f28619f2e30 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:564 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f28619f2e30 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10412 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f28b0010798' [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f28619f2e30 to 0x7f28b0010960 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x7f28619f2e30 to 0x7f28b0010960 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f28619f2e30 to 0x7f28b0010960 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f28619f2e30 to 0x7f28b0010960 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4665 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f28b0010798' [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10695 process_sdp: We're settling with these formats: (gsm|ulaw|alaw) [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:10702 process_sdp: We have an owner, now see if we need to change this call [Aug 1 15:12:04] DEBUG[7370][C-00000000]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:6564 update_call_counter: Updating call counter for outgoing call [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:16423 build_route: build_route: Contact hop: [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52104' into... [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52104'. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52104' into... [Aug 1 15:12:04] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52104'. [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'ACK sip:888' onto UDP socket destined for 192.168.1.49:52104 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: app_stack.c:974 gosub_run: SIP/8888-00000001 Original location: ato,,1 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: app_stack.c:579 gosub_exec: Channel SIP/8888-00000001 has no datastore, so we're allocating one. [Aug 1 15:12:04] DEBUG[7864][C-00000000]: app_stack.c:978 gosub_run: Gosub exited with status 0 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(userfield) result is '(null)' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '8888' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'Set' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(cstfld) result is '(null)' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '8888' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'Set' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'Return' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: app_stack.c:1040 gosub_run: Spawn extension (ato,,1) exited with -1 on 'SIP/8888-00000001' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: app_stack.c:1066 gosub_run: SIP/8888-00000001 Ending location: ato,,1 [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 1 15:12:04] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888 [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1' [Aug 1 15:12:04] DEBUG[7380]: 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 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:7147 sip_answer: SIP answering channel: SIP/7777-00000000 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:13585 transmit_response_with_sdp: Setting framing from config on incoming call [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:13134 add_sdp: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:13135 add_sdp: ** Our prefcodec: (nothing) [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:13271 add_sdp: -- Done with adding codecs to SDP [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:13471 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) [Aug 1 15:12:04] DEBUG[7864][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: features.c:4433 ast_bridge_call: bridge answer set, chan answer set [Aug 1 15:12:04] DEBUG[7864][C-00000000]: features.c:4254 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/8888-00000001 since we're bridging [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 1 15:12:04] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777 [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 1 15:12:04] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1' [Aug 1 15:12:04] DEBUG[7380]: 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 1 15:12:04] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0099310a187b33ff (Checking From) --From tag 4b500b5f57e06d39 --To-tag as04afa7f6 [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:28533 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Aug 1 15:12:04] DEBUG[7370][C-00000000]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '0099310a187b33ff' of Response 32163: Match Found [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:4333 ast_rtp_read: 0x7f28b0015d80 -- Probation learning mode pass with source address 192.168.1.49:40008 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:3446 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:3481 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:3343 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f28b4013278' [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:4333 ast_rtp_read: 0x7f28b4018480 -- Probation learning mode pass with source address 192.168.1.49:2480 [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:3446 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 1 15:12:04] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:3481 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [Aug 1 15:12:06] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 (Checking From) --From tag 2776247a --To-tag as7ff1e0e7 [Aug 1 15:12:06] DEBUG[7370][C-00000000]: chan_sip.c:28533 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Aug 1 15:12:06] DEBUG[7370][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52104' into... [Aug 1 15:12:06] DEBUG[7370][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52104'. [Aug 1 15:12:06] DEBUG[7370][C-00000000]: chan_sip.c:3387 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 [Aug 1 15:12:06] DEBUG[7370][C-00000000]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f28b0010798' [Aug 1 15:12:06] DEBUG[7370][C-00000000]: chan_sip.c:27149 handle_request_bye: Received bye, issuing owner hangup [Aug 1 15:12:06] DEBUG[7370][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:52104 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:7650 ast_generic_bridge: Didn't get a frame from channel: SIP/8888-00000001 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:2926 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:8144 ast_channel_bridge: Bridge stops bridging channels SIP/7777-00000000 and SIP/8888-00000001 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:2662 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/7777-00000000' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: pbx.c:5005 pbx_extension_helper: Launching 'NoOp' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: cdr_radius.c:216 radius_log: Unable to create RADIUS record. CDR not recorded! [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x26a2848) called (obj->txf = (nil)) [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:684 find_table: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: id INTEGER [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: clid VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: src VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: dst VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: dcontext VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: channel VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: dstchannel VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: lastapp VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: lastdata VARCHAR(80) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: start DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: answer DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: end DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: duration INT(11) NOT NULL DEFAULT 0 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: billsec INT(11) NOT NULL DEFAULT 0 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: disposition VARCHAR(45) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: amaflags INT(11) NOT NULL DEFAULT 0 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: accountcode VARCHAR(20) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: uniqueid VARCHAR(32) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: userfield VARCHAR(255) NOT NULL DEFAULT '' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_config_sqlite.c:613 find_table_cb: Found field: PRIMARY KEY (id) [Aug 1 15:12:06] DEBUG[7864][C-00000000]: 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-00000000','SIP/8888-00000001','Dial','SIP/8888,20,tirU(subAnswer)','2017-08-01 15:12:02','2017-08-01 15:12:04','2017-08-01 15:12:06','4','2','ANSWERED','DOCUMENTATION','1501589522.0',':8888') [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:2841 ast_hangup: Hanging up channel 'SIP/8888-00000001' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: chan_sip.c:6929 sip_hangup: Hangup call SIP/8888-00000001, SIP callid 0b09ea083ebb445e59104b4e4e5e42f9@192.168.1.67:5060 [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f28b0010798' [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 1 15:12:06] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 8888 [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/8888' state '1' [Aug 1 15:12:06] DEBUG[7380]: 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 1 15:12:06] DEBUG[7864][C-00000000]: app_dial.c:3120 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 1 15:12:06] DEBUG[7864][C-00000000]: pbx.c:6789 __ast_pbx_run: Spawn extension (buh,8888,2) exited non-zero on 'SIP/7777-00000000' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:2662 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/7777-00000000' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: channel.c:2841 ast_hangup: Hanging up channel 'SIP/7777-00000000' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: chan_sip.c:6929 sip_hangup: Hangup call SIP/7777-00000000, SIP callid 0099310a187b33ff [Aug 1 15:12:06] DEBUG[7864][C-00000000]: res_rtp_asterisk.c:4755 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f28b4013278' [Aug 1 15:12:06] DEBUG[7864][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.49:52101' into... [Aug 1 15:12:06] DEBUG[7864][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '52101'. [Aug 1 15:12:06] DEBUG[7864][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'BYE sip:0x1' onto UDP socket destined for 192.168.1.49:52101 [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 1 15:12:06] DEBUG[7344]: chan_sip.c:29982 sip_devicestate: Checking device state for peer 7777 [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:477 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 1 15:12:06] DEBUG[7344]: devicestate.c:452 devstate_event: device 'SIP/7777' state '1' [Aug 1 15:12:06] DEBUG[7380]: 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 1 15:12:06] DEBUG[7370]: chan_sip.c:9057 find_call: = Looking for Call ID: 0099310a187b33ff (Checking To) --From tag as04afa7f6 --To-tag 4b500b5f57e06d39 [Aug 1 15:12:06] DEBUG[7370][C-00000000]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '0099310a187b33ff' of Request 102: Match Found [Aug 1 15:12:06] DEBUG[7370]: chan_sip.c:6379 sip_pvt_dtor: Destroying SIP dialog 0099310a187b33ff [Aug 1 15:12:06] DEBUG[7370]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x7f28b4013278' asterisk11*CLI> exit