pbxv6*CLI> core set debug 9999 Core debug was OFF and is now 9999. [Feb 27 10:16:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02g5ann418f5tn5rj (Checking From) --From tag lvprn92ras --To-tag [Feb 27 10:16:23] DEBUG[6396]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.136', our source address is '192.168.99.254'. [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_WS with address 192.168.99.254:5060 [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for uuk02g5ann418f5tn5rj - INVITE (No RTP) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:28642 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: ice,replaces,outbound" [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -ice- [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1762 parse_sip_options: Found no match for SIP option: ice (Please file bug report!) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces- [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -outbound- [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: outbound [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 522 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 522 [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02g5ann418f5tn5rj (Checking From) --From tag lvprn92ras --To-tag as71baca6a [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:28642 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'uuk02g5ann418f5tn5rj' of Response 5000: Match Found [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02g5ann418f5tn5rj (Checking From) --From tag lvprn92ras --To-tag [Feb 27 10:16:23] DEBUG[6396]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:28642 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 12884 for RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:12884 (12884) for RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x37c2c90' is setup and ready to go [Feb 27 10:16:23] == DTLS ECDH initialized (automatic), faster PFS enabled [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'pbxv6' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'pbxv6' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:23] == Using SIP RTP CoS mark 5 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:5798 do_setnat: Setting NAT on RTP to On [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP o=- 498934442243886251 2 IN IP4 127.0.0.1... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] == Using UDPTL CoS mark 5 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:7792 initialize_udptl: Setting NAT on UDPTL to On [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP a=group:BUNDLE audio... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10261 process_sdp: Processing session-level SDP a=msid-semantic: WMS 2GhWJd7uFxPVqVX4oOKirPEHcTAzD1y4dErM... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 111 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 103 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 104 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 106 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 105 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 13 based on m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 126 format for m type on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP c=IN IP4 186.54.167.236... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp:51440 IN IP4 186.54.167.236... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:2367935622 1 udp 2122260223 192.168.99.136 57179 typ host generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:2367935622 2 udp 2122260222 192.168.99.136 51440 typ host generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'active' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'active' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:3282053238 1 tcp 1518280447 192.168.99.136 9 typ host tcptype active generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'active' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'active' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:3282053238 2 tcp 1518280446 192.168.99.136 9 typ host tcptype active generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:1101982485 2 udp 1686052606 186.54.167.236 51440 typ srflx raddr 192.168.99.136 rport 51440 generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:1101982485 1 udp 1686052607 186.54.167.236 57179 typ srflx raddr 192.168.99.136 rport 57179 generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ice-ufrag:199H... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ice-pwd:+x3R+Czc1Fuh+R3wWfTydk2s... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=fingerprint:sha-256 59:66:07:93:AB:C3:3F:D3:78:61:36:CD:B6:21:92:64:F4:DD:46:EB:E8:E6:94:5D:A0:70:2A:BB:61:89:30:11... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=setup:actpass... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp-fb:111 transport-cc... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=fmtp:111 minptime=10;useinbandfec=1... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 103 on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 104 on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 106 on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 105 on 0x7fbf96ff0320 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:2894015814 cname:Jrcn9W/b3ixBqwq9... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:2894015814 msid:2GhWJd7uFxPVqVX4oOKirPEHcTAzD1y4dErM cc29bc49-e781-46bb-bc75-5ef513bac7e0... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:2894015814 mslabel:2GhWJd7uFxPVqVX4oOKirPEHcTAzD1y4dErM... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:2894015814 label:cc29bc49-e781-46bb-bc75-5ef513bac7e0... UNSUPPORTED OR FAILED. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: acl.c:957 ast_ouraddrfor: For destination '186.54.167.236', our source address is '192.168.99.254'. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x3794a78) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x37949f8) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x3794a38) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 13 (0x37d3418) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 111 (0x3785ec8) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 126 (0x37d3898) from 0x7fbf96ff0320 to 0x37c2e58 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_rtp_asterisk.c:4916 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:11012 process_sdp: We're settling with these formats: (alaw|ulaw) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:26226 handle_request_invite: Checking SIP call limits for device 1099 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:8153 sip_new: *** Our native formats are (alaw) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:8154 sip_new: *** Joint capabilities are (alaw|ulaw) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:8155 sip_new: *** Our capabilities are (alaw|ulaw) [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:8156 sip_new: *** AST_CODEC_CHOOSE formats are alaw [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:8189 sip_new: This channel will not be able to handle video. [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:26430 handle_request_invite: SIP/1099-0000002f: New call is still down.... Trying... [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 100' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 483 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 483 [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:16:23] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:16:23] DEBUG[4135]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Feb 27 10:16:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'SIP/1099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: INUSE [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: INUSE [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:16:23] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '12345678' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'SELECT welcome, schedule , name , form , interactions FROM queues WHERE did= '12345678' AND direction = 'inbound'' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:16:23] > Found no rows [SELECT welcome, schedule , name , form , interactions FROM queues WHERE did= '12345678' AND direction = 'inbound'] [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function ODBC_Data(SELECT welcome\, schedule \, name \, form \, interactions FROM queues WHERE did= '12345678' AND direction = 'inbound') result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:1] Set("SIP/1099-0000002f", "HASH(queue)=") in new stack [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: HASH(queue)= [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: HASH(queue)= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:2] Set("SIP/1099-0000002f", "CHANNEL(Language)=es") in new stack [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 2 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: CHANNEL(Language)=es [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 2 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: CHANNEL(Language)=es [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1099' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:3] Set("SIP/1099-0000002f", "__Ani=1099") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 3 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __Ani=1099 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 3 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __Ani=1099 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(queue,name) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:4] Set("SIP/1099-0000002f", "CDR(campaign)=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 4 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: CDR(campaign)= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 4 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: CDR(campaign)= [Feb 27 10:16:23] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Answer' [Feb 27 10:16:23] -- Executing [12345678@entrantes:5] Answer("SIP/1099-0000002f", "0") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Answer AppData: 0 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Answer AppData: 0 [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:16:23] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:16:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:7412 sip_answer: SIP answering channel: SIP/1099-0000002f [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:13406 add_sdp: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:13407 add_sdp: ** Our prefcodec: (nothing) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:13577 add_sdp: -- Done with adding codecs to SDP [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:13602 add_sdp: Setting framing on incoming call: 0 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:853 ast_rtp_ice_set_role: Set role to CONTROLLED (0x37c2c90) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:647 ice_reset_session: Resetting ICE for RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:649 ice_reset_session: Nevermind. ICE isn't ready for a reset [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:787 ast_rtp_ice_start: Successfully created ICE checklist (0x37c2c90) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:13790 add_sdp: Done building SDP. Settling with this capability: (alaw|ulaw) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 1386 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 1386 [Feb 27 10:16:23] DEBUG[4182]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[4182]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[4182]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.136', our source address is '192.168.99.254'. [Feb 27 10:16:23] DEBUG[4182]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:16:23] DEBUG[4182]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:16:23] DEBUG[4182]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:16:23] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02g5ann418f5tn5rj (Checking From) --From tag lvprn92ras --To-tag as7de25249 [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:28642 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Feb 27 10:16:23] DEBUG[6396][C-000000ac]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'uuk02g5ann418f5tn5rj' of Response 5001: Match Found [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_srtp.c:516 ast_srtp_add_stream: Adding new policy for SSRC 1029431448 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_srtp.c:516 ast_srtp_add_stream: Adding new policy for SSRC 1029431448 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x3762ce0 -- Probation learning mode pass with source address 192.168.99.136:57179 [Feb 27 10:16:23] > 0x3762ce0 -- Probation passed - setting RTP source address to 192.168.99.136:57179 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1488201383' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1488201383,,%d) result is '27' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1488201383' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1488201383,,%m) result is '02' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1488201383' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1488201383,,%Y) result is '2017' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1488201383' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1488201383,,%R) result is '10:16' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1488201383' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1488201383,,%R) result is '10:16' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(campaign) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'select sound from holidays WHERE day = '27' AND month = '02' AND (year = '2017' OR year = '*') AND substring(timerange,1,5) <= '10:16' AND substring(timerange,7) >= '10:16' AND (campaign ='*' OR campaign ='')' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:16:23] > Found no rows [select sound from holidays WHERE day = '27' AND month = '02' AND (year = '2017' OR year = '*') AND substring(timerange,1,5) <= '10:16' AND substring(timerange,7) >= '10:16' AND (campaign ='*' OR campaign ='')] [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function ODBC_Data(select sound from holidays WHERE day = '27' AND month = '02' AND (year = '2017' OR year = '*') AND substring(timerange,1,5) <= '10:16' AND substring(timerange,7) >= '10:16' AND (campaign ='*' OR campaign ='')) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:6] Set("SIP/1099-0000002f", "sound=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 6 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: sound= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 6 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: sound= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'sound' is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:16:23] -- Executing [12345678@entrantes:7] GotoIf("SIP/1099-0000002f", "1?11:8") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 7 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: GotoIf AppData: 1?11:8 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 7 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: GotoIf AppData: 1?11:8 [Feb 27 10:16:23] -- Goto (entrantes,12345678,11) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '12345678' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:11] Set("SIP/1099-0000002f", "__DID=12345678") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 11 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __DID=12345678 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 11 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __DID=12345678 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(queue,interactions) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:12] Set("SIP/1099-0000002f", "__VirtualHold=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 12 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __VirtualHold= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 12 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: __VirtualHold= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(queue,welcome) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:13] Set("SIP/1099-0000002f", "welcome=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 13 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: welcome= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 13 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: welcome= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'welcome' (from 'welcome}' len 7) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'welcome' is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CUT(welcome,;,1) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:14] Set("SIP/1099-0000002f", "Bienvenida=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 14 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: Bienvenida= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 14 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: Bienvenida= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'welcome' (from 'welcome}' len 7) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'welcome' is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CUT(welcome,;,2) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:15] Set("SIP/1099-0000002f", "FueraDeHora=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 15 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: FueraDeHora= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 15 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: FueraDeHora= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(queue,schedule) result is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:16] Set("SIP/1099-0000002f", "schedule=") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 16 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: schedule= [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 16 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: schedule= [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'schedule' (from 'schedule}' len 8) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'schedule' is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function FIELDQTY(schedule,&) result is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:17] Set("SIP/1099-0000002f", "cantidad=0") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 17 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: cantidad=0 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 17 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: cantidad=0 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:23] -- Executing [12345678@entrantes:18] Set("SIP/1099-0000002f", "dentroDeHora=0") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 18 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: dentroDeHora=0 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 18 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Set AppData: dentroDeHora=0 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'cantidad' is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'dentroDeHora' is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'While' [Feb 27 10:16:23] -- Executing [12345678@entrantes:19] While("SIP/1099-0000002f", "0") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 19 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: While AppData: 0 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 19 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: While AppData: 0 [Feb 27 10:16:23] -- Jumping to priority 25 [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'dentroDeHora' is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:16:23] -- Executing [12345678@entrantes:26] GotoIf("SIP/1099-0000002f", "0?29:27") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 26 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: GotoIf AppData: 0?29:27 [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 26 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: GotoIf AppData: 0?29:27 [Feb 27 10:16:23] -- Goto (entrantes,12345678,27) [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FueraDeHora' is '' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Playback' [Feb 27 10:16:23] -- Executing [12345678@entrantes:27] Playback("SIP/1099-0000002f", ",") in new stack [Feb 27 10:16:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 27 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Playback AppData: , [Feb 27 10:16:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 27 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Playback AppData: , [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: channel.c:5680 set_format: Channel SIP/1099-0000002f setting write format path: gsm -> alaw [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to alaw [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 27 10:16:23] -- Playing '.gsm' (language 'es') [Feb 27 10:16:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 56 bytes [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136:51440' into... [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port '51440'. [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254:12885' into... [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port '12885'. [Feb 27 10:16:23] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 32 bytes [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136:51440' into... [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port '51440'. [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254:12885' into... [Feb 27 10:16:23] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port '12885'. [Feb 27 10:16:24] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 03f3634118484a4255e5f256364daf58@192.168.99.250:5060 (Checking From) --From tag as3cd7b7b3 --To-tag [Feb 27 10:16:24] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.250', our source address is '192.168.99.254'. [Feb 27 10:16:24] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.250:5060' into... [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.250' and port '5060'. [Feb 27 10:16:24] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 03f3634118484a4255e5f256364daf58@192.168.99.250:5060 - OPTIONS (No RTP) [Feb 27 10:16:24] DEBUG[4202]: chan_sip.c:28642 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.250' into... [Feb 27 10:16:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.250' and port ''. [Feb 27 10:16:24] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.99.250:5060 [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:5680 set_format: Channel SIP/1099-0000002f setting write format path: alaw -> alaw [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '12345678' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Goto' [Feb 27 10:16:24] -- Executing [12345678@entrantes:28] Goto("SIP/1099-0000002f", "entrantes,12345678,9") in new stack [Feb 27 10:16:24] -- Goto (entrantes,12345678,9) [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'VoiceMail' [Feb 27 10:16:24] -- Executing [12345678@entrantes:9] VoiceMail("SIP/1099-0000002f", "1000@voicemail,") in new stack [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: app_voicemail.c:6546 leave_voicemail: Before find_user [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 28 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Goto AppData: entrantes,12345678,9 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 28 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Goto AppData: entrantes,12345678,9 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: VoiceMail AppData: 1000@voicemail, [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: VoiceMail AppData: 1000@voicemail, [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_config_odbc.c:116 custom_prepare: Skip: 0; SQL: SELECT * FROM voicemail WHERE mailbox = ? AND context = ? [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_config_odbc.c:132 custom_prepare: Parameter 1 ('mailbox') = '1000' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_config_odbc.c:132 custom_prepare: Parameter 2 ('context') = 'voicemail' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:16:24] WARNING[7652][C-000000ac]: app_voicemail.c:6549 leave_voicemail: No entry in voicemail config file for '1000' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Hangup' [Feb 27 10:16:24] -- Executing [12345678@entrantes:10] Hangup("SIP/1099-0000002f", "") in new stack [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:4346 __ast_pbx_run: Spawn extension (entrantes,12345678,10) exited non-zero on 'SIP/1099-0000002f' [Feb 27 10:16:24] == Spawn extension (entrantes, 12345678, 10) exited non-zero on 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'MEMBERNAME' is NULL [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:24] -- Executing [h@entrantes:1] Set("SIP/1099-0000002f", "CHANNEL(accountcode)=") in new stack [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:24] -- Executing [h@entrantes:2] Set("SIP/1099-0000002f", "CDR(userfield)=TESTUSERFIELD1314") in new stack [Feb 27 10:16:24] DEBUG[4150]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/1099-0000002f - start 1488201383.761249 answer 1488201383.773456 end 1488201384.850406 dispo ANSWERED [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 10 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Hangup AppData: [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 10 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: 12345678 Application: Hangup AppData: [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 10 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Cause: 16 [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: 12345678 Priority: 10 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Cause: 16 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: h Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CHANNEL(accountcode)= [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 OldAccountCode: Integra [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: entrantes Exten: h Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CHANNEL(accountcode)= [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 2 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(userfield)=TESTUSERFIELD1314 [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 1 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 OldAccountCode: Integra [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 2 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(userfield)=TESTUSERFIELD1314 [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:24] -- Executing [h@entrantes:3] Set("SIP/1099-0000002f", "CDR(direction)=incoming") in new stack [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 3 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(direction)=incoming [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 3 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(direction)=incoming [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '16' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:16:24] -- Executing [h@entrantes:4] Set("SIP/1099-0000002f", "CDR(causecode)=16") in new stack [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 4 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(causecode)=16 [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 4 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Set AppData: CDR(causecode)=16 [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' [Feb 27 10:16:24] -- Executing [h@entrantes:5] NoOp("SIP/1099-0000002f", "") in new stack [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'customerfeedback' is NULL [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:16:24] -- Executing [h@entrantes:6] GotoIf("SIP/1099-0000002f", "1?8:7") in new stack [Feb 27 10:16:24] -- Goto (entrantes,h,8) [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'ABANDONED' is NULL [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'VirtualHold' is '' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:16:24] -- Executing [h@entrantes:8] GotoIf("SIP/1099-0000002f", "0?10:9") in new stack [Feb 27 10:16:24] -- Goto (entrantes,h,9) [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:2875 pbx_extension_helper: Launching 'Hangup' [Feb 27 10:16:24] -- Executing [h@entrantes:9] Hangup("SIP/1099-0000002f", "") in new stack [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: pbx.c:4157 ast_pbx_h_exten_run: Spawn extension (entrantes,h,9) exited non-zero on 'SIP/1099-0000002f' [Feb 27 10:16:24] == Spawn extension (entrantes, h, 9) exited non-zero on 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: channel.c:2728 ast_hangup: Hanging up channel 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: chan_sip.c:7154 sip_hangup: Hangup call SIP/1099-0000002f, SIP callid uuk02g5ann418f5tn5rj [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: chan_sip.c:3753 __sip_xmit: Trying to put 'BYE sip:5ve' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 597 [Feb 27 10:16:24] DEBUG[7652][C-000000ac]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 597 [Feb 27 10:16:24] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:16:24] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:16:24] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 1 (Not in use) [Feb 27 10:16:24] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'SIP/1099' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: NoOp AppData: [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 5 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: NoOp AppData: [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 6 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: GotoIf AppData: 1?8:7 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 8 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: GotoIf AppData: 0?10:9 [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 6 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: GotoIf AppData: 1?8:7 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Hangup AppData: [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 8 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: GotoIf AppData: 0?10:9 [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: NOT_INUSE [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Extension: h Application: Hangup AppData: [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: NOT_INUSE [Feb 27 10:16:24] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:16:24] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/1099-0000002f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Context: entrantes Exten: h Priority: 9 Uniqueid: 1488201383.108 Linkedid: 1488201383.108 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:16:24] DEBUG[4150]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:16:24] DEBUG[4150]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,lastapp,duration,billsec,disposition,amaflags,accountcode,userfield,uniqueid,causecode,direction,linkedid,sequence) VALUES ({ ts '2017-02-27 10:16:23' },'"" <1099>','1099','12345678','entrantes','SIP/1099-0000002f','Hangup',1,1,'ANSWERED',3,'Integra','TESTUSERFIELD1314','1488201383.108','16','incoming','1488201383.108',88)] [Feb 27 10:16:24] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:16:24] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:16:24] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 1 (Not in use) [Feb 27 10:16:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:24] DEBUG[4150]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(clid)})},${CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 24) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(start) result is '2017-02-27 10:16:23' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(2017-02-27 10:16:23) result is '"2017-02-27 10:16:23"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(clid)})' (from 'CSV_QUOTE(${CDR(clid)})},${CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 23) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(clid)' (from 'CDR(clid)})' len 9) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(clid) result is '"" <1099>' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE("" <1099>) result is '""""" <1099>"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 22) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(src) result is '1099' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1099) result is '"1099"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 22) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dst) result is '12345678' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(12345678) result is '"12345678"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dcontext) result is 'entrantes' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(entrantes) result is '"entrantes"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(channel)})' (from 'CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 26) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(channel) result is 'SIP/1099-0000002f' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(SIP/1099-0000002f) result is '"SIP/1099-0000002f"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(dstchannel)})' (from 'CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 29) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dstchannel) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(lastapp)})' (from 'CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 26) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(lastapp) result is 'Hangup' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Hangup) result is '"Hangup"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(lastdata)})' (from 'CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(lastdata) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(duration)})' (from 'CSV_QUOTE(${CDR(duration)})},${CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(duration)' (from 'CDR(duration)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(duration) result is '1' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1) result is '"1"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(billsec)})' (from 'CSV_QUOTE(${CDR(billsec)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 26) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(billsec)' (from 'CDR(billsec)})' len 12) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(billsec) result is '1' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1) result is '"1"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(disposition)})' (from 'CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 30) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(disposition) result is 'ANSWERED' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(ANSWERED) result is '"ANSWERED"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(amaflags)})' (from 'CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(amaflags) result is 'DOCUMENTATION' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(accountcode)})' (from 'CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 30) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(accountcode) result is 'Integra' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Integra) result is '"Integra"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(userfield)})' (from 'CSV_QUOTE(${CDR(userfield)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 28) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(userfield) result is 'TESTUSERFIELD1314' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(TESTUSERFIELD1314) result is '"TESTUSERFIELD1314"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(uniqueid)})' (from 'CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(uniqueid) result is '1488201383.108' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1488201383.108) result is '"1488201383.108"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(type)})' (from 'CSV_QUOTE(${CDR(type)})},${CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 23) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(type)' (from 'CDR(type)})' len 9) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(type) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(guid)})' (from 'CSV_QUOTE(${CDR(guid)})},${CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 23) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(guid)' (from 'CDR(guid)})' len 9) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(guid) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(causecode)})' (from 'CSV_QUOTE(${CDR(causecode)})},${CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 28) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(causecode)' (from 'CDR(causecode)})' len 14) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(causecode) result is '16' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(16) result is '"16"' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(campaign)})' (from 'CSV_QUOTE(${CDR(campaign)})},${CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 27) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(campaign)' (from 'CDR(campaign)})' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(campaign) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(sequence)' (from 'CDR(sequence)},${CSV_QUOTE(${CDR(dialerbase)})} ' len 13) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(sequence) result is '88' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CSV_QUOTE(${CDR(dialerbase)})' (from 'CSV_QUOTE(${CDR(dialerbase)})} ' len 29) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dialerbase)' (from 'CDR(dialerbase)})' len 15) [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dialerbase) result is '' [Feb 27 10:16:24] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:16:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:24] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02g5ann418f5tn5rj (Checking To) --From tag as7de25249 --To-tag lvprn92ras [Feb 27 10:16:24] DEBUG[6396][C-000000ac]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'uuk02g5ann418f5tn5rj' of Request 102: Match Found [Feb 27 10:16:25] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog uuk02g5ann418f5tn5rj [Feb 27 10:16:25] DEBUG[4202]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x37c2c90' [Feb 27 10:16:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:16:26] DEBUG[4202]: chan_sip.c:4361 __sip_autodestruct: Auto destroying SIP dialog '5afafca545c280501dc6831c2202c9de@192.168.99.250:5060' [Feb 27 10:16:26] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 5afafca545c280501dc6831c2202c9de@192.168.99.250:5060 [Feb 27 10:16:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:16:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:16:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels