asterisk-gw*CLI> core set debug 5 Core debug was OFF and is now 5. [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 (Checking From) --From tag as54dca8f4 --To-tag [2015-12-29 21:55:51] DEBUG[3561]: acl.c:979 ast_ouraddrfor: For destination '172.16.10.173', our source address is '172.16.15.196'. [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:4028 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.15.196:5060 [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into... [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port '5060'. [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:8780 sip_alloc: Allocating new SIP dialog for 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 - INVITE (No RTP) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:28315 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: sip/reqresp_parser.c:1607 parse_sip_options: Begin: parsing SIP "Supported: replaces, timer" [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -replaces- [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: replaces [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -timer- [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: timer [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port '5060'. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.10.173:5060 [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 (Checking From) --From tag as54dca8f4 --To-tag as590fa6b1 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:28315 handle_incoming: **** Received ACK (6) - Command in SIP ACK [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:4563 __sip_ack: Stopping retransmission on '0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060' of Response 102: Match Found [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 (Checking From) --From tag as54dca8f4 --To-tag [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.15.196' into... [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.15.196' and port ''. [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.15.196' into... [2015-12-29 21:55:51] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.15.196' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:28315 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port '5060'. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x38d4a08' [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: res_rtp_asterisk.c:1989 ast_rtp_new: Allocated port 10232 for RTP instance '0x38d4a08' [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x38d4a08' is setup and ready to go [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: res_rtp_asterisk.c:4124 ast_rtp_prop_set: Setup RTCP on RTP instance '0x38d4a08' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:5733 do_setnat: Setting NAT on RTP to Off [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10059 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10059 process_sdp: Processing session-level SDP o=root 695923972 695923973 IN IP4 172.16.10.173... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10059 process_sdp: Processing session-level SDP s=Asterisk PBX 13.6.0... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10059 process_sdp: Processing session-level SDP c=IN IP4 172.16.10.173... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10059 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 111 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 4 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 112 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 5 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 10 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 118 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 7 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 110 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 117 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 119 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 97 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 102 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 115 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 116 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 107 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:4 annexa=no... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:112 AAL2-G726-32/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:5 DVI4/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:10 L16/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:118 L16/16000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:7 LPC/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:117 speex/16000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:119 speex/32000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:102 G7221/16000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:102 bitrate=32000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:115 G7221/32000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:115 bitrate=48000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:116 G719/48000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:116 bitrate=64000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 107 on 0x7f3251e6b1d0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:107 opus/48000/2... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=maxptime:20... UNSUPPORTED OR FAILED. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10504 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: res_rtp_asterisk.c:4171 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x38d4a08' [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 4 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 5 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 7 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 10 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 97 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 102 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 110 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 111 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 112 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 115 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 116 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 117 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 118 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 119 from 0x7f3251e6b1d0 to 0x38d4bd0 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: res_rtp_asterisk.c:4090 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x38d4a08' [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:10775 process_sdp: We're settling with these formats: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|siren7|siren14|g719|speex32) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:25685 handle_request_invite: Checking SIP call limits for device 0099992 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:6678 update_call_counter: Updating call counter for incoming call [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.15.196' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.15.196' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.10.173' into... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:25139 handle_request_invite_st: Incoming INVITE with 'timer' option supported [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:7955 sip_new: *** Our native formats are (alaw) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:7956 sip_new: *** Joint capabilities are (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|siren7|siren14|g719|speex32) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:7957 sip_new: *** Our capabilities are (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14|testlaw|g719|speex32|slin12|slin24|slin32|slin44|slin48|slin96|slin192|silk8|silk12|silk16|silk24) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:7958 sip_new: *** AST_CODEC_CHOOSE formats are alaw [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:7986 sip_new: This channel will not be able to handle video. [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:16325 build_route: build_route: Contact hop: [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:29281 start_session_timer: Session timer started: 469945 - 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 900000ms [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:25885 handle_request_invite: SIP/0099991-000008bd: New call is still down.... Trying... [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.16.10.173:5060 [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 0099991 [2015-12-29 21:55:51] DEBUG[3142]: chan_sip.c:29771 sip_devicestate: Checking device state for peer 0099991 [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:467 do_state_change: Changing state for SIP/0099991 - state 1 (Not in use) [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:442 devstate_event: device 'SIP/0099991' state '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk-sip-0099991:1] Set("SIP/0099991-000008bd", "GROUP()=OUT_19") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '1107' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Goto' -- Executing [1107@from-trunk-sip-0099991:2] Goto("SIP/0099991-000008bd", "from-trunk,1107,1") in new stack -- Goto (from-trunk,1107,1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'NoOp' -- Executing [1107@from-trunk:1] NoOp("SIP/0099991-000008bd", "Changing Callerid (add prefix)") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1101) result is '4' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf' -- Executing [1107@from-trunk:2] ExecIf("SIP/0099991-000008bd", "0 ?Set(CALLERID(num)=01101)") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FROM_DID' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk:3] Set("SIP/0099991-000008bd", "CDR(did)=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf' -- Executing [1107@from-trunk:4] ExecIf("SIP/0099991-000008bd", "0 ?Set(CALLERID(name)=1101)") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk:5] Set("SIP/0099991-000008bd", "CHANNEL(musicclass)=default") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk:6] Set("SIP/0099991-000008bd", "__MOHCLASS=default") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Ringing' -- Executing [1107@from-trunk:7] Ringing("SIP/0099991-000008bd", "") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 172.16.10.173:5060 [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERPRES() result is 'allowed_not_screened' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk:8] Set("SIP/0099991-000008bd", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@from-trunk:9] Set("SIP/0099991-000008bd", "CALLERPRES()=allowed_not_screened") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '1107' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Goto' -- Executing [1107@from-trunk:10] Goto("SIP/0099991-000008bd", "AllSintek,1107,1") in new stack -- Goto (AllSintek,1107,1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '1107' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Goto' -- Executing [1107@AllSintek:1] Goto("SIP/0099991-000008bd", "AllSintek_rulematch,1107,1") in new stack -- Goto (AllSintek_rulematch,1107,1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Macro' -- Executing [1107@AllSintek_rulematch:1] Macro("SIP/0099991-000008bd", "user-callerid,LIMIT,EXTERNAL,") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1451415351.7746' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("SIP/0099991-000008bd", "TOUCH_MONITOR=1451415351.7746") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?1101:) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:2] Set("SIP/0099991-000008bd", "AMPUSER=1101") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/0099991-000008bd' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:3] GotoIf("SIP/0099991-000008bd", "0?report") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:11810 pbx_builtin_gotoif: Not taking any branch [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:4] ExecIf("SIP/0099991-000008bd", "1?Set(REALCALLERIDNUM=1101)") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: db.c:376 db_get_common: Unable to find key '1101/user' in family 'DEVICE' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: func_db.c:151 function_db_read: DB: DEVICE/1101/user not found in database. [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(DEVICE/1101/user) result is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("SIP/0099991-000008bd", "AMPUSER=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:6] GotoIf("SIP/0099991-000008bd", "0?limit") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:11810 pbx_builtin_gotoif: Not taking any branch [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: db.c:376 db_get_common: Unable to find key '/cidname' in family 'AMPUSER' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: func_db.c:151 function_db_read: DB: AMPUSER//cidname not found in database. [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER//cidname) result is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:7] Set("SIP/0099991-000008bd", "AMPUSERCIDNAME=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:8] GotoIf("SIP/0099991-000008bd", "1?report") in new stack -- Goto (macro-user-callerid,s,15) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:15] GotoIf("SIP/0099991-000008bd", "1?continue") in new stack -- Goto (macro-user-callerid,s,28) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:28] Set("SIP/0099991-000008bd", "CALLERID(number)=1101") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:29] Set("SIP/0099991-000008bd", "CALLERID(name)=TEST 123") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:30] Set("SIP/0099991-000008bd", "CDR(cnum)=1101") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:31] Set("SIP/0099991-000008bd", "CDR(cnam)=TEST 123") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4516 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'ru' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'ru' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:32] Set("SIP/0099991-000008bd", "CHANNEL(language)=ru") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FROM_DID' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FROM_DID' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf' -- Executing [1107@AllSintek_rulematch:2] GosubIf("SIP/0099991-000008bd", "0?sub-diversion-header,s,1()") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@AllSintek_rulematch:3] Set("SIP/0099991-000008bd", "INTRACOMPANYROUTE=YES") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?default:default) result is 'default' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@AllSintek_rulematch:4] Set("SIP/0099991-000008bd", "MOHCLASS=default") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [1107@AllSintek_rulematch:5] Set("SIP/0099991-000008bd", "_NODEST=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '1107' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Gosub' -- Executing [1107@AllSintek_rulematch:6] Gosub("SIP/0099991-000008bd", "sub-record-check,s,1(out,1107,)") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_stack.c:579 gosub_exec: Channel SIP/0099991-000008bd has no datastore, so we're allocating one. [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'out' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '1107' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_stack.c:621 gosub_exec: Setting 'ARG3' to '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:1] Set("SIP/0099991-000008bd", "REC_POLICY_MODE_SAVE=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'BLINDTRANSFER' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:2] GotoIf("SIP/0099991-000008bd", "1?check") in new stack -- Goto (sub-record-check,s,7) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:7] Set("SIP/0099991-000008bd", "__MON_FMT=wav") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_STATUS' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:8] GotoIf("SIP/0099991-000008bd", "1?next") in new stack -- Goto (sub-record-check,s,11) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(out) result is '3' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:11] ExecIf("SIP/0099991-000008bd", "0?Return()") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0fef17805ed3866c3a527fcc207bd6e8@172.16.15.196:5060 (Checking To) --From tag as53d8d55a --To-tag as24ac6ff1 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:4525 __sip_ack: Acked pending invite 102 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:4563 __sip_ack: Stopping retransmission on '0fef17805ed3866c3a527fcc207bd6e8@172.16.15.196:5060' of Request 102: Match Found [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:22735 handle_response_invite: SIP response 401 to standard invite [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'ACK sip:110' onto UDP socket destined for 172.16.15.194:5060 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:21847 do_proxy_auth: Auth attempt 1 on INVITE [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13153 add_sdp: This call needs video offers, but there's no video support enabled! [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13167 add_sdp: This call needs text offers, but there's no text support enabled ! [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13201 add_sdp: ** Our capability: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14|testlaw|g719|speex32|slin12|slin24|slin32|slin44|slin48|slin96|slin192|silk8|silk12|silk16|silk24) Video flag: False Text flag: False [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13202 add_sdp: ** Our prefcodec: (alaw) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13338 add_sdp: -- Done with adding codecs to SDP [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:13533 add_sdp: Done building SDP. Settling with this capability: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|jpeg|png|h261|h263|h263p|h264|mpeg4|red|t140|siren7|siren14|testlaw|g719|speex32|slin12|slin24|slin32|slin44|slin48|slin96|slin192|silk8|silk12|silk16|silk24) [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.15.194:5060 [2015-12-29 21:55:51] DEBUG[3575]: app_queue.c:1859 handle_statechange: Device 'SIP/0099991' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2015-12-29 21:55:51] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0fef17805ed3866c3a527fcc207bd6e8@172.16.15.196:5060 (Checking To) --From tag as53d8d55a --To-tag as24ac6ff1 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:4525 __sip_ack: Acked pending invite 103 [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:4563 __sip_ack: Stopping retransmission on '0fef17805ed3866c3a527fcc207bd6e8@172.16.15.196:5060' of Request 103: Match Found [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:22735 handle_response_invite: SIP response 403 to standard invite [2015-12-29 21:55:51] DEBUG[3561][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'ACK sip:110' onto UDP socket destined for 172.16.15.194:5060 [2015-12-29 21:55:51] WARNING[3561][C-00003cc1]: chan_sip.c:23127 handle_response_invite: Received response: "Forbidden" from '"TEST 123" ;tag=as53d8d55a' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/001001-000008be' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:7061 sip_hangup: Hangup call SIP/001001-000008be, SIP callid 0fef17805ed3866c3a527fcc207bd6e8@172.16.15.196:5060 [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:4171 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x3acc598' == Everyone is busy/congested at this time (1:0/0/1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_dial.c:3102 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL. [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Dial [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '21' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/0099991-000008bd", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 21") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Noop [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG4' is 'on' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/0099991-000008bd", "1?continue,1:s-CHANUNAVAIL,1") in new stack -- Goto (macro-dialout-trunk,continue,1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '21' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'NoOp' -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/0099991-000008bd", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 21 - failing through to other trunks") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Noop [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Set' -- Executing [continue@macro-dialout-trunk:2] Set("SIP/0099991-000008bd", "CALLERID(number)=") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Set [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Macro' -- Executing [1107@AllSintek_rulematch:8] Macro("SIP/0099991-000008bd", "outisbusy,") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Progress' -- Executing [s@macro-outisbusy:1] Progress("SIP/0099991-000008bd", "") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:13647 transmit_response_with_sdp: Setting framing from config on incoming call [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:13201 add_sdp: ** Our capability: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|siren7|siren14|g719|speex32) Video flag: True Text flag: True [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:13202 add_sdp: ** Our prefcodec: (nothing) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:13338 add_sdp: -- Done with adding codecs to SDP [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:13533 add_sdp: Done building SDP. Settling with this capability: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilbc|g726aal2|g722|slin16|siren7|siren14|g719|speex32) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 172.16.10.173:5060 [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Progress [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'EMERGENCYROUTE' is NULL [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-outisbusy:2] GotoIf("SIP/0099991-000008bd", "0?emergency,1") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:11810 pbx_builtin_gotoif: Not taking any branch [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'INTRACOMPANYROUTE' is 'YES' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-outisbusy:3] GotoIf("SIP/0099991-000008bd", "1?intracompany,1") in new stack -- Goto (macro-outisbusy,intracompany,1) [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Playback' -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/0099991-000008bd", "custom/abonent-ne-otvechaet-pls-try-ag-lat, noanswer") in new stack [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: channel.c:5405 set_format: Set channel SIP/0099991-000008bd to write format slin [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:2884 ast_rtp_write: Ooh, format changed from unknown to alaw [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:2919 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160 [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:2777 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x38d4a08' [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: channel.c:3594 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'custom/abonent-ne-otvechaet-pls-try-ag-lat.slin' (language 'ru') [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 001001 [2015-12-29 21:55:51] DEBUG[3142]: chan_sip.c:29771 sip_devicestate: Checking device state for peer 001001 [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:467 do_state_change: Changing state for SIP/001001 - state 1 (Not in use) [2015-12-29 21:55:51] DEBUG[3142]: devicestate.c:442 devstate_event: device 'SIP/001001' state '1' [2015-12-29 21:55:51] DEBUG[3575]: app_queue.c:1859 handle_statechange: Device 'SIP/001001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2015-12-29 21:55:51] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:3758 ast_rtp_read: 0x3362d60 -- Probation learning mode pass with source address 172.16.10.173:17894 > 0x3362d60 -- Probation passed - setting RTP source address to 172.16.10.173:17894 [2015-12-29 21:55:52] DEBUG[3561]: chan_sip.c:8780 sip_alloc: Allocating new SIP dialog for 7b301dd556c8199b029878a825d4db53@127.0.1.1:5060 - OPTIONS (No RTP) [2015-12-29 21:55:52] DEBUG[3561]: acl.c:979 ast_ouraddrfor: For destination '195.91.157.85', our source address is '81.18.134.131'. [2015-12-29 21:55:52] DEBUG[3561]: chan_sip.c:4028 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 81.18.134.131:5060 [2015-12-29 21:55:52] DEBUG[3561]: chan_sip.c:8569 change_callid_pvt: SIP call-id changed from '7b301dd556c8199b029878a825d4db53@127.0.1.1:5060' to '441b76c258b103b8751ef1873dd85f77@81.18.134.131:5060' [2015-12-29 21:55:52] DEBUG[3561]: chan_sip.c:3514 initialize_initreq: Initializing initreq for method OPTIONS - callid 441b76c258b103b8751ef1873dd85f77@81.18.134.131:5060 [2015-12-29 21:55:52] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 195.91.157.85:5060 [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 195.91.157.85:5060 [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 732dcbba38a5f70c54bda00864c10319@172.16.23.196:5060 (Checking From) --From tag as2768154c --To-tag [2015-12-29 21:55:53] DEBUG[3561]: acl.c:979 ast_ouraddrfor: For destination '172.16.23.196', our source address is '172.16.15.196'. [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:4028 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.15.196:5060 [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.23.196:5060' into... [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.23.196' and port '5060'. [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:8780 sip_alloc: Allocating new SIP dialog for 732dcbba38a5f70c54bda00864c10319@172.16.23.196:5060 - OPTIONS (No RTP) [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:28315 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.15.196' into... [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.15.196' and port ''. [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.23.196' into... [2015-12-29 21:55:53] DEBUG[3561]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.23.196' and port ''. [2015-12-29 21:55:53] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.23.196:5060 [2015-12-29 21:55:54] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 195.91.157.85:5060 [2015-12-29 21:55:54] DEBUG[3561]: chan_sip.c:4135 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #469939)) [2015-12-29 21:55:54] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 195.154.58.113:5070 [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 195.91.157.85:5060 [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:3594 ast_settimeout_full: Scheduling timer at (2000 requested / 1000 actual) timer ticks per second [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:3594 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:3594 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:3594 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:5405 set_format: Set channel SIP/0099991-000008bd to write format alaw [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: Playback [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Congestion' -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/0099991-000008bd", "20") in new stack [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: chan_sip.c:3871 __sip_xmit: Trying to put 'SIP/2.0 503' onto UDP socket destined for 172.16.10.173:5060 [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: chan_sip.c:3527 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: app_macro.c:428 _macro_exec: Spawn extension (macro-outisbusy,intracompany,2) exited non-zero on 'SIP/0099991-000008bd' in macro 'outisbusy' == Spawn extension (macro-outisbusy, intracompany, 2) exited non-zero on 'SIP/0099991-000008bd' in macro 'outisbusy' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:6566 __ast_pbx_run: Spawn extension (AllSintek_rulematch,1107,8) exited non-zero on 'SIP/0099991-000008bd' == Spawn extension (AllSintek_rulematch, 1107, 8) exited non-zero on 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Macro' -- Executing [h@AllSintek_rulematch:1] Macro("SIP/0099991-000008bd", "hangupcall,") in new stack [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'USE_CONFIRMATION' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'RINGGROUP_INDEX' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3671 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'UNIQCHAN' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-hangupcall:1] GotoIf("SIP/0099991-000008bd", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'ONETOUCH_RECFILE' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CDR(recordingfile) result is '(null)' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'ONETOUCH_RECFILE' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-hangupcall:3] ExecIf("SIP/0099991-000008bd", "0?Set(CDR(recordingfile)=)") in new stack [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ONETOUCH_RECFILE' (from 'ONETOUCH_RECFILE}"!="" & "${CDR(recordingfile)}"=""' len 16) [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'ONETOUCH_RECFILE' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CDR(recordingfile)' (from 'CDR(recordingfile)}"=""' len 18) [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4516 ast_str_substitute_variables_full: Function CDR(recordingfile) result is '(null)' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ONETOUCH_RECFILE' (from 'ONETOUCH_RECFILE})' len 16) [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:3668 ast_str_retrieve_variable: Result of 'ONETOUCH_RECFILE' is NULL [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:4883 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-hangupcall:4] Hangup("SIP/0099991-000008bd", "") in new stack [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: app_macro.c:428 _macro_exec: Spawn extension (macro-hangupcall,s,4) exited non-zero on 'SIP/0099991-000008bd' in macro 'hangupcall' == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/0099991-000008bd' in macro 'hangupcall' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: pbx.c:6082 ast_pbx_h_exten_run: Spawn extension (AllSintek_rulematch,h,1) exited non-zero on 'SIP/0099991-000008bd' == Spawn extension (AllSintek_rulematch, h, 1) exited non-zero on 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/0099991-000008bd' [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: chan_sip.c:7061 sip_hangup: Hangup call SIP/0099991-000008bd, SIP callid 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: res_rtp_asterisk.c:4171 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x38d4a08' [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:9177 find_call: = Looking for Call ID: 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 (Checking From) --From tag as54dca8f4 --To-tag as3d9c11ec [2015-12-29 21:55:55] DEBUG[3561][C-00003cc1]: chan_sip.c:28315 handle_incoming: **** Received ACK (6) - Command in SIP ACK [2015-12-29 21:55:55] DEBUG[3561][C-00003cc1]: chan_sip.c:4563 __sip_ack: Stopping retransmission on '0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060' of Response 103: Match Found [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:29233 stop_session_timer: Session timer stopped: 469945 - 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:6826 sip_destroy: Destroying SIP dialog 0beb84246ce39aca0bf5d2606e80b6ef@172.16.10.173:5060 [2015-12-29 21:55:55] DEBUG[3561]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x38d4a08' [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 0099991 [2015-12-29 21:55:55] DEBUG[3142]: chan_sip.c:29771 sip_devicestate: Checking device state for peer 0099991 [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:467 do_state_change: Changing state for SIP/0099991 - state 1 (Not in use) [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:442 devstate_event: device 'SIP/0099991' state '1' [2015-12-29 21:55:55] DEBUG[3575]: app_queue.c:1859 handle_statechange: Device 'SIP/0099991' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: cdr_mysql.c:336 mysql_log: Inserting a CDR record. [2015-12-29 21:55:55] DEBUG[7978][C-00003cc1]: cdr_mysql.c:339 mysql_log: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`cnum`,`cnam`) VALUES ('2015-12-29 21:55:51','\"TEST 123\" <1101>','1101','1107','AllSintek_rulematch','SIP/0099991-000008bd','SIP/001001-000008be','Congestion','20','4','0','FAILED','3','1451415351.7746','1101','TEST 123') [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 0099991 [2015-12-29 21:55:55] DEBUG[3142]: chan_sip.c:29771 sip_devicestate: Checking device state for peer 0099991 [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:467 do_state_change: Changing state for SIP/0099991 - state 1 (Not in use) [2015-12-29 21:55:55] DEBUG[3142]: devicestate.c:442 devstate_event: device 'SIP/0099991' state '1' [2015-12-29 21:55:55] DEBUG[3575]: app_queue.c:1859 handle_statechange: Device 'SIP/0099991' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:4419 __sip_autodestruct: Auto destroying SIP dialog 'SBCbrrac1tun8qnr17aqc7v1t8n8ttu89f1@SoftX3000' [2015-12-29 21:55:55] DEBUG[3561]: chan_sip.c:6826 sip_destroy: Destroying SIP dialog SBCbrrac1tun8qnr17aqc7v1t8n8ttu89f1@SoftX3000 [2015-12-29 21:55:56] DEBUG[3561]: chan_sip.c:3871 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 195.91.157.85:5060 [2015-12-29 21:55:56] DEBUG[3561]: chan_sip.c:6826 sip_destroy: Destroying SIP dialog 441b76c258b103b8751ef1873dd85f77@81.18.134.131:5060