root@pbxv6:~# asterisk -r [Feb 27 10:19:02] Asterisk 13.14.0, Copyright (C) 1999 - 2014, Digium, Inc. and others. [Feb 27 10:19:02] Created by Mark Spencer [Feb 27 10:19:02] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Feb 27 10:19:02] This is free software, with components licensed under the GNU General Public [Feb 27 10:19:02] License version 2 and other licenses; you are welcome to redistribute it under [Feb 27 10:19:02] certain conditions. Type 'core show license' for details. [Feb 27 10:19:02] ========================================================================= [Feb 27 10:19:02] Connected to Asterisk 13.14.0 currently running on pbxv6 (pid = 4132) [Feb 27 10:19:03] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:03] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:03] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:04] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:04] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:04] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:05] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:05] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:05] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' pbxv6*CLI> core set verbose 999 Console verbose was OFF and is now 999. pbxv6*CLI> [Feb 27 10:19:06] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:06] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:06] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' pbxv6*CLI> [Feb 27 10:19:07] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:07] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:07] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 314bfc6f594da0d623228bc86899ee21@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:07] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.109', our source address is '192.168.99.254'. [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '314bfc6f594da0d623228bc86899ee21@127.0.1.1:5060' to '49e883df68211ab76f8b305024211353@192.168.99.254:5060' [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 49e883df68211ab76f8b305024211353@192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.99.109:5062 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 49e883df68211ab76f8b305024211353@192.168.99.254:5060 (Checking To) --From tag as6b23f70a --To-tag 251256571 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '49e883df68211ab76f8b305024211353@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 49e883df68211ab76f8b305024211353@192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 568b8d4b0b84e988476a1c5061f39394@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:07] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.134', our source address is '192.168.99.254'. [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '568b8d4b0b84e988476a1c5061f39394@127.0.1.1:5060' to '0177d15a579baf794209e3c8713ea73f@192.168.99.254:5060' [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 0177d15a579baf794209e3c8713ea73f@192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.99.134:5062 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 0177d15a579baf794209e3c8713ea73f@192.168.99.254:5060 (Checking To) --From tag as423a74c9 --To-tag 2292943171 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '0177d15a579baf794209e3c8713ea73f@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 0177d15a579baf794209e3c8713ea73f@192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 0a2b604f0374072315db2b6973db35dc@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:07] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.135', our source address is '192.168.99.254'. [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '0a2b604f0374072315db2b6973db35dc@127.0.1.1:5060' to '633166e30f8ec8401eca376030330d04@192.168.99.254:5060' [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 633166e30f8ec8401eca376030330d04@192.168.99.254:5060 [Feb 27 10:19:07] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.99.135:5062 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 633166e30f8ec8401eca376030330d04@192.168.99.254:5060 (Checking To) --From tag as2b73fc24 --To-tag 448452615 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '633166e30f8ec8401eca376030330d04@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 633166e30f8ec8401eca376030330d04@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 6c0125d9367776a659fdadbe4731732c@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:08] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.136', our source address is '192.168.99.254'. [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_WS with address 192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '6c0125d9367776a659fdadbe4731732c@127.0.1.1:5060' to '653e88875eb1a3eb491092b354ce702e@192.168.99.254:5060' [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 653e88875eb1a3eb491092b354ce702e@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:19:08] DEBUG[4202]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 607 [Feb 27 10:19:08] DEBUG[4202]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 607 [Feb 27 10:19:08] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: 653e88875eb1a3eb491092b354ce702e@192.168.99.254:5060 (Checking To) --From tag as61fc1dfe --To-tag bkfrbphfac [Feb 27 10:19:08] DEBUG[6396]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '653e88875eb1a3eb491092b354ce702e@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 6b6093fe7aa3acec2b510a8276b18674@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:08] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.247', our source address is '192.168.99.254'. [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '6b6093fe7aa3acec2b510a8276b18674@127.0.1.1:5060' to '72cd225725b39ccb66ac812349268eca@192.168.99.254:5060' [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 72cd225725b39ccb66ac812349268eca@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.99.247:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 7f85a2775d4bc4ab75fad2f9419696c5@127.0.1.1:5060 - OPTIONS (No RTP) [Feb 27 10:19:08] DEBUG[4202]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.250', our source address is '192.168.99.254'. [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:8781 change_callid_pvt: SIP call-id changed from '7f85a2775d4bc4ab75fad2f9419696c5@127.0.1.1:5060' to '43d70c6462d7e80e13f84ce94afca7ce@192.168.99.254:5060' [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3396 initialize_initreq: Initializing initreq for method OPTIONS - callid 43d70c6462d7e80e13f84ce94afca7ce@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:3753 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.99.250:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 653e88875eb1a3eb491092b354ce702e@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 72cd225725b39ccb66ac812349268eca@192.168.99.254:5060 (Checking To) --From tag as7b44ba95 --To-tag as076375a2 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '72cd225725b39ccb66ac812349268eca@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 72cd225725b39ccb66ac812349268eca@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 43d70c6462d7e80e13f84ce94afca7ce@192.168.99.254:5060 (Checking To) --From tag as63cecccf --To-tag as7b83a21a [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:4537 __sip_ack: Stopping retransmission on '43d70c6462d7e80e13f84ce94afca7ce@192.168.99.254:5060' of Request 102: Match Found [Feb 27 10:19:08] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 43d70c6462d7e80e13f84ce94afca7ce@192.168.99.254:5060 [Feb 27 10:19:08] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:08] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:08] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:09] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:09] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:09] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:10] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:10] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:10] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:11] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:11] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:11] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:12] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:12] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:12] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:13] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:13] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:13] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:14] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:14] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:14] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:15] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:15] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:15] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:16] DEBUG[4206]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1488201556 Interval: 30 [Feb 27 10:19:16] DEBUG[4206]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [Feb 27 10:19:16] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:16] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:16] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:16] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02d0iacl2qct7vfia (Checking From) --From tag m8as2t5dj3 --To-tag [Feb 27 10:19:16] DEBUG[6396]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.136', our source address is '192.168.99.254'. [Feb 27 10:19:16] DEBUG[6396]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_WS with address 192.168.99.254:5060 [Feb 27 10:19:16] DEBUG[6396]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for uuk02d0iacl2qct7vfia - INVITE (No RTP) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:28642 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: ice,replaces,outbound" [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -ice- [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1762 parse_sip_options: Found no match for SIP option: ice (Please file bug report!) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces- [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -outbound- [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: outbound [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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:19:16] DEBUG[6396][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 518 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 518 [Feb 27 10:19:16] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02d0iacl2qct7vfia (Checking From) --From tag m8as2t5dj3 --To-tag as4ae8e5ae [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:28642 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'uuk02d0iacl2qct7vfia' of Response 6660: Match Found [Feb 27 10:19:16] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02d0iacl2qct7vfia (Checking From) --From tag m8as2t5dj3 --To-tag [Feb 27 10:19:16] DEBUG[6396]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:28642 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 13762 for RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:13762 (13762) for RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x37c2c90' is setup and ready to go [Feb 27 10:19:16] == DTLS ECDH initialized (automatic), faster PFS enabled [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'pbxv6' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'pbxv6' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:16] == Using SIP RTP CoS mark 5 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:5798 do_setnat: Setting NAT on RTP to On [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP o=- 7325515184120512193 2 IN IP4 127.0.0.1... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] == Using UDPTL CoS mark 5 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:7792 initialize_udptl: Setting NAT on UDPTL to On [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP a=group:BUNDLE audio... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10261 process_sdp: Processing session-level SDP a=msid-semantic: WMS Q1tuP4jmPh8SPTbsDr6HYY9wLm1Xuskizi3r... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 111 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 103 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 104 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 106 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 105 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 13 based on m type on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP c=IN IP4 186.54.167.236... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp:61145 IN IP4 186.54.167.236... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:2367935622 1 udp 2122260223 192.168.99.136 53163 typ host generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:2367935622 2 udp 2122260222 192.168.99.136 61145 typ host generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'active' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'active' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'active' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'active' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:1101982485 1 udp 1686052607 186.54.167.236 53163 typ srflx raddr 192.168.99.136 rport 53163 generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '186.54.167.236' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '186.54.167.236' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=candidate:1101982485 2 udp 1686052606 186.54.167.236 61145 typ srflx raddr 192.168.99.136 rport 61145 generation 0 network-id 1 network-cost 10... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ice-ufrag:53zW... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ice-pwd:0xYAzpY/8MchA3jClSna08Ht... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=fingerprint:sha-256 FA:AD:78:7C:30:58:80:4E:3F:C2:1D:7B:81:3C:C2:4D:25:8B:70:A8:3B:3B:30:86:9A:D9:5E:97:82:A4:3F:E1... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=setup:actpass... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtcp-fb:111 transport-cc... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=fmtp:111 minptime=10;useinbandfec=1... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 103 on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 104 on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 106 on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 105 on 0x7fbf96ff0330 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:853043641 cname:iW6bkFlX4hL1MbJ1... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:853043641 msid:Q1tuP4jmPh8SPTbsDr6HYY9wLm1Xuskizi3r d4c8ad63-99ac-4851-acd2-9410341beac6... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:853043641 mslabel:Q1tuP4jmPh8SPTbsDr6HYY9wLm1Xuskizi3r... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:10716 process_sdp: Processing media-level (audio) SDP a=ssrc:853043641 label:d4c8ad63-99ac-4851-acd2-9410341beac6... UNSUPPORTED OR FAILED. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: acl.c:957 ast_ouraddrfor: For destination '186.54.167.236', our source address is '192.168.99.254'. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x37e3328) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x37e32a8) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x37e32e8) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 13 (0x37f3898) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 111 (0x37ab908) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 126 (0x37f3d18) from 0x7fbf96ff0330 to 0x37c2e58 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:4916 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x37c2c90' [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:11012 process_sdp: We're settling with these formats: (alaw|ulaw) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:26226 handle_request_invite: Checking SIP call limits for device 1099 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '254.ucontactcloud.com' into... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '254.ucontactcloud.com' and port ''. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:8153 sip_new: *** Our native formats are (alaw) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:8154 sip_new: *** Joint capabilities are (alaw|ulaw) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:8155 sip_new: *** Our capabilities are (alaw|ulaw) [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:8156 sip_new: *** AST_CODEC_CHOOSE formats are alaw [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:8189 sip_new: This channel will not be able to handle video. [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: chan_sip.c:26430 handle_request_invite: SIP/1099-00000030: New call is still down.... Trying... [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: 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:19:16] DEBUG[6396][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 475 [Feb 27 10:19:16] DEBUG[6396][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 475 [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:19:16] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:19:16] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:19:16] DEBUG[4135]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Feb 27 10:19:16] 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:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: INUSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: INUSE [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(accountcode) result is 'Integra' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'select did,name from queues where name in (select queue_name from queue_members where membername = 'Integra') and direction = 'Outbound'' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:19:16] > Found no rows [select did,name from queues where name in (select queue_name from queue_members where membername = 'Integra') and direction = 'Outbound'] [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function ODBC_Data(select did\,name from queues where name in (select queue_name from queue_members where membername = 'Integra') and direction = 'Outbound') result is '' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:1] Set("SIP/1099-00000030", "HASH(Result)=") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: HASH(Result)= [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: HASH(Result)= [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(Result,name) result is '' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:2] Set("SIP/1099-00000030", "__OUTQUEUE=") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 2 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __OUTQUEUE= [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 2 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __OUTQUEUE= [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:3] Set("SIP/1099-00000030", "VOLUME(TX)=3") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 3 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: VOLUME(TX)=3 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 3 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: VOLUME(TX)=3 [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:4] Set("SIP/1099-00000030", "VOLUME(RX)=3") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 4 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: VOLUME(RX)=3 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 4 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: VOLUME(RX)=3 [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:5] Set("SIP/1099-00000030", "CALLERID(name-pres)=allowed_passed_screen") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 5 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CALLERID(name-pres)=allowed_passed_screen [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 5 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CALLERID(name-pres)=allowed_passed_screen [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(accountcode) result is 'Integra' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:6] Set("SIP/1099-00000030", "__AGENT=Integra") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 6 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __AGENT=Integra [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 6 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __AGENT=Integra [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1099' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(1099/LOCAL) result is 'TRUE' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:7] Set("SIP/1099-00000030", "local-var=TRUE") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 7 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: local-var=TRUE [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 7 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: local-var=TRUE [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'local-var' is 'TRUE' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:19:16] -- Executing [9123@locales:8] GotoIf("SIP/1099-00000030", "1?11:9") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 8 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GotoIf AppData: 1?11:9 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 8 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GotoIf AppData: 1?11:9 [Feb 27 10:19:16] -- Goto (locales,9123,11) [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'GUID' [Feb 27 10:19:16] -- Executing [9123@locales:11] GUID("SIP/1099-00000030", "__guid") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GUID AppData: __guid [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GUID AppData: __guid [Feb 27 10:19:16] -- app_guidgen: new guid c1ebcb80-87ff-4efc-971a-eb8680a7400a [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'guid' is 'c1ebcb80-87ff-4efc-971a-eb8680a7400a' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:12] Set("SIP/1099-00000030", "CDR(guid)=c1ebcb80-87ff-4efc-971a-eb8680a7400a") in new stack [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(guid)=c1ebcb80-87ff-4efc-971a-eb8680a7400a [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(guid)=c1ebcb80-87ff-4efc-971a-eb8680a7400a [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '9123' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:13] Set("SIP/1099-00000030", "__Ani=123") in new stack [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '9123' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:14] Set("SIP/1099-00000030", "__DIALED=9123") in new stack [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTQUEUE' is '' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:15] Set("SIP/1099-00000030", "CDR(campaign)=") in new stack [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 13 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __Ani=123 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 13 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __Ani=123 [Feb 27 10:19:16] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) )[Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 14 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __DIALED=9123 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 14 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __DIALED=9123 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 15 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(campaign)= [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 15 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(campaign)= [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AGENT' is 'Integra' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:16] Set("SIP/1099-00000030", "CDR(accountcode)=Integra") in new stack [Feb 27 10:19:16] WARNING[4150]: func_cdr.c:395 cdr_write_callback: Using the CDR function to set 'accountcode' is deprecated. Please use the CHANNEL function instead. [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 16 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(accountcode)=Integra [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 16 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: CDR(accountcode)=Integra [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'guid' is 'c1ebcb80-87ff-4efc-971a-eb8680a7400a' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:17] Set("SIP/1099-00000030", "__idLlamada=c1ebcb80-87ff-4efc-971a-eb8680a7400a") in new stack [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1099' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(1099/REC) result is 'FALSE' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:18] Set("SIP/1099-00000030", "rec-var=FALSE") in new stack [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'rec-var' is 'FALSE' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [Feb 27 10:19:16] -- Executing [9123@locales:19] GotoIf("SIP/1099-00000030", "0?23:20") in new stack [Feb 27 10:19:16] -- Goto (locales,9123,20) [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '9123' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:16] -- Executing [9123@locales:20] Set("SIP/1099-00000030", "__REALDIALED=123") in new stack [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '9123' [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Dial' [Feb 27 10:19:16] -- Executing [9123@locales:21] Dial("SIP/1099-00000030", "Khomp/B0C30/123,60,TtKk,") in new stack [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 17 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __idLlamada=c1ebcb80-87ff-4efc-971a-eb8680a7400a [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 17 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __idLlamada=c1ebcb80-87ff-4efc-971a-eb8680a7400a [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 18 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: rec-var=FALSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 18 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: rec-var=FALSE [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 19 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GotoIf AppData: 0?23:20 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 19 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: GotoIf AppData: 0?23:20 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 20 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __REALDIALED=123 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Dial AppData: Khomp/B0C30/123,60,TtKk, [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 20 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Set AppData: __REALDIALED=123 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: 9123 Application: Dial AppData: Khomp/B0C30/123,60,TtKk, [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __REALDIALED from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __idLlamada from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __DIALED from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __Ani from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __guid from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __AGENT from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] DEBUG[7938][C-000000ad]: channel.c:6651 ast_channel_inherit_variables: Inheriting variable __OUTQUEUE from SIP/1099-00000030 to Khomp/B0C30-0.0. [Feb 27 10:19:16] -- Called Khomp/B0C30/123 [Feb 27 10:19:16] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Khomp - B0C30 [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for Khomp/B0C30 - state 1 (Not in use) [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Khomp - B0C30 [Feb 27 10:19:16] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:16] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for Khomp/B0C30 - state 1 (Not in use) [Feb 27 10:19:16] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 1 ChannelStateDesc: Rsrvd CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Extension: 9123 Application: AppDial AppData: (Outgoing Line) [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 1 ChannelStateDesc: Rsrvd CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 OldAccountCode: [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Extension: 9123 Application: AppDial AppData: (Outgoing Line) [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 3 ChannelStateDesc: Dialing CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 DestChannel: Khomp/B0C30-0.0 DestChannelState: 3 DestChannelStateDesc: Dialing DestCallerIDNum: 9123 DestCallerIDName: DestConnectedLineNum: 1099 DestConnectedLineName: DestLanguage: en DestAccountCode: Integra DestContext: entrantes-00-30 DestExten: 9123 DestPriority: 1 DestUniqueid: 1488201556.111 DestLinkedid: 1488201556.110 DialString: B0C30/123 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 OldAccountCode: [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 2 ChannelStateDesc: OffHook CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:16] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 3 ChannelStateDesc: Dialing CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 DestChannel: Khomp/B0C30-0.0 DestChannelState: 3 DestChannelStateDesc: Dialing DestCallerIDNum: 9123 DestCallerIDName: DestConnectedLineNum: 1099 DestConnectedLineName: DestLanguage: en DestAccountCode: Integra DestContext: entrantes-00-30 DestExten: 9123 DestPriority: 1 DestUniqueid: 1488201556.111 DestLinkedid: 1488201556.110 DialString: B0C30/123 [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:16] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:17] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:17] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:17] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:17] DEBUG[4256]: manager.c:6317 process_message: Running action 'Ping' [Feb 27 10:19:17] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: OperatorRegistry Privilege: system,all Channel: Khomp/B0C34 Operator: 74801 [Feb 27 10:19:17] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: OperatorRegistry Privilege: system,all Channel: Khomp/B0C34 Operator: 74801 [Feb 27 10:19:17] DEBUG[4255]: manager.c:6317 process_message: Running action 'Ping' [Feb 27 10:19:18] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:18] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:18] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:19] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:19] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:19] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:19] -- Khomp/B0C30-0.0 is ringing [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 180' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 491 [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 491 [Feb 27 10:19:19] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Khomp - B0C30 [Feb 27 10:19:19] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:19] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:19] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for Khomp/B0C30 - state 2 (In use) [Feb 27 10:19:19] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 27 10:19:19] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: INUSE [Feb 27 10:19:19] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: INUSE [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:19] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: AntennaLevel Privilege: system,all Channel: Khomp/B0C34 Signal: 57% [Feb 27 10:19:20] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: AntennaLevel Privilege: system,all Channel: Khomp/B0C34 Signal: 57% [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:20] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:20] -- Khomp/B0C30-0.0 is making progress passing it to SIP/1099-00000030 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:13406 add_sdp: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:13407 add_sdp: ** Our prefcodec: (nothing) [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:13577 add_sdp: -- Done with adding codecs to SDP [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:13602 add_sdp: Setting framing on incoming call: 0 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:853 ast_rtp_ice_set_role: Set role to CONTROLLED (0x37c2c90) [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:647 ice_reset_session: Resetting ICE for RTP instance '0x37c2c90' [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:649 ice_reset_session: Nevermind. ICE isn't ready for a reset [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:787 ast_rtp_ice_start: Successfully created ICE checklist (0x37c2c90) [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:13790 add_sdp: Done building SDP. Settling with this capability: (alaw|ulaw) [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 183' onto WS socket destined for 192.168.99.136:57837 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 1394 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 1394 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to alaw [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3469 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x37c2c90' [Feb 27 10:19:20] DEBUG[4182]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:20] DEBUG[4182]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:20] DEBUG[4182]: acl.c:957 ast_ouraddrfor: For destination '192.168.99.136', our source address is '192.168.99.254'. [Feb 27 10:19:20] DEBUG[4182]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:19:20] DEBUG[4182]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136' into... [Feb 27 10:19:20] DEBUG[4182]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port ''. [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_srtp.c:516 ast_srtp_add_stream: Adding new policy for SSRC 1855714600 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_srtp.c:516 ast_srtp_add_stream: Adding new policy for SSRC 1855714600 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x3762ce0 -- Probation learning mode pass with source address 192.168.99.136:53163 [Feb 27 10:19:20] > 0x3762ce0 -- Probation passed - setting RTP source address to 192.168.99.136:53163 [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 56 bytes [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136:61145' into... [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port '61145'. [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254:13763' into... [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port '13763'. [Feb 27 10:19:20] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 32 bytes [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136:61145' into... [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port '61145'. [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254:13763' into... [Feb 27 10:19:20] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port '13763'. [Feb 27 10:19:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:21] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:22] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:22] -- Khomp/B0C30-0.0 answered SIP/1099-00000030 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:7412 sip_answer: SIP answering channel: SIP/1099-00000030 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:13406 add_sdp: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:13407 add_sdp: ** Our prefcodec: (nothing) [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:13577 add_sdp: -- Done with adding codecs to SDP [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:13602 add_sdp: Setting framing on incoming call: 0 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:853 ast_rtp_ice_set_role: Set role to CONTROLLED (0x37c2c90) [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: chan_sip.c:13790 add_sdp: Done building SDP. Settling with this capability: (alaw|ulaw) [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: 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:19:22] DEBUG[7938][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 1380 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 1380 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: dahdi/bridge_native_dahdi.c:714 native_bridge_compatible: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: Cannot use native DAHDI. Must have two channels. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_native_rtp.c:425 native_rtp_bridge_compatible: Bridge '3a618386-e0e9-4953-9dbe-ce702f562282' can not use native RTP bridge as two channels are required [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:501 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:794 bridge_base_init: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: calling simple_bridge technology constructor [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:802 bridge_base_init: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: calling simple_bridge technology start [Feb 27 10:19:22] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Khomp - B0C30 [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: 9123 Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 DestChannel: Khomp/B0C30-0.0 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 9123 DestCallerIDName: DestConnectedLineNum: 1099 DestConnectedLineName: DestLanguage: en DestAccountCode: Integra DestContext: entrantes-00-30 DestExten: DestPriority: 1 DestUniqueid: 1488201556.111 DestLinkedid: 1488201556.110 DialStatus: ANSWER [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 DestChannel: Khomp/B0C30-0.0 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 9123 DestCallerIDName: DestConnectedLineNum: 1099 DestConnectedLineName: DestLanguage: en DestAccountCode: Integra DestContext: entrantes-00-30 DestExten: DestPriority: 1 DestUniqueid: 1488201556.111 DestLinkedid: 1488201556.110 DialStatus: ANSWER [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Feb 27 10:19:22] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for Khomp/B0C30 - state 2 (In use) [Feb 27 10:19:22] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:19:22] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:19:22] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 2 (In use) [Feb 27 10:19:22] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: INUSE [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: INUSE [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x370bab0(Khomp/B0C30-0.0) is joining [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Extension: Application: AppDial AppData: (Outgoing Line) [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Extension: Application: AppDial AppData: (Outgoing Line) [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: pushing 0x370bab0(Khomp/B0C30-0.0) [Feb 27 10:19:22] -- Channel Khomp/B0C30-0.0 joined 'simple_bridge' basic-bridge <3a618386-e0e9-4953-9dbe-ce702f562282> [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: dahdi/bridge_native_dahdi.c:714 native_bridge_compatible: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: Cannot use native DAHDI. Must have two channels. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge_native_rtp.c:425 native_rtp_bridge_compatible: Bridge '3a618386-e0e9-4953-9dbe-ce702f562282' can not use native RTP bridge as two channels are required [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:1046 smart_bridge_operation: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282 is already using the new technology. [Feb 27 10:19:22] DEBUG[7943][C-000000ad]: bridge.c:432 bridge_channel_complete_join: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x370bab0(Khomp/B0C30-0.0) is joining simple_bridge technology [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x2cf8120(SIP/1099-00000030) is joining [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: pushing 0x2cf8120(SIP/1099-00000030) [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_channel.c:414 channel_fill_empty_peeraccount: Setting channel SIP/1099-00000030 peeraccount with channel Khomp/B0C30-0.0 accountcode 'Integra'. [Feb 27 10:19:22] -- Channel SIP/1099-00000030 joined 'simple_bridge' basic-bridge <3a618386-e0e9-4953-9dbe-ce702f562282> [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: dahdi/bridge_native_dahdi.c:652 native_bridge_is_capable: Channel 'Khomp/B0C30-0.0' has DTMF hooks. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: dahdi/bridge_native_dahdi.c:721 native_bridge_compatible: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: Cannot use native DAHDI. Channel 'Khomp/B0C30-0.0' not compatible. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_native_rtp.c:338 native_rtp_bridge_compatible_check: Bridge '3a618386-e0e9-4953-9dbe-ce702f562282' can not use native RTP bridge as channel 'SIP/1099-00000030' has features which prevent it [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:1046 smart_bridge_operation: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282 is already using the new technology. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:432 bridge_channel_complete_join: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x2cf8120(SIP/1099-00000030) is joining simple_bridge technology [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3072 ast_rtp_change_source: Changing ssrc from 1855714600 to 1925960274 due to a source change [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:3075 ast_rtp_change_source: Changing ssrc for SRTP from 1855714600 to 1925960274 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_srtp.c:516 ast_srtp_add_stream: Adding new policy for SSRC 1925960274 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_srtp.c:546 ast_srtp_change_source: Couldn't remove stream (13) [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: dahdi/bridge_native_dahdi.c:652 native_bridge_is_capable: Channel 'Khomp/B0C30-0.0' has DTMF hooks. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: dahdi/bridge_native_dahdi.c:721 native_bridge_compatible: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: Cannot use native DAHDI. Channel 'Khomp/B0C30-0.0' not compatible. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge_native_rtp.c:338 native_rtp_bridge_compatible_check: Bridge '3a618386-e0e9-4953-9dbe-ce702f562282' can not use native RTP bridge as channel 'SIP/1099-00000030' has features which prevent it [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: bridge.c:1046 smart_bridge_operation: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282 is already using the new technology. [Feb 27 10:19:22] DEBUG[4150]: cdr.c:1293 cdr_object_finalize: Finalized CDR for Khomp/B0C30-0.0 - start 1488201556.886137 answer 1488201562.414752 end 1488201562.423974 dispo ANSWERED [Feb 27 10:19:22] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:22] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02d0iacl2qct7vfia (Checking From) --From tag m8as2t5dj3 --To-tag as067d1913 [Feb 27 10:19:22] DEBUG[6396][C-000000ad]: chan_sip.c:28642 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Feb 27 10:19:22] DEBUG[6396][C-000000ad]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'uuk02d0iacl2qct7vfia' of Response 6661: Match Found [Feb 27 10:19:22] WARNING[7938][C-000000ad]: chan_iax2.c:1239 jb_warning_output: Resyncing the jb. last_delay 0, this delay -181932484, threshold 1000, new offset 181932484 [Feb 27 10:19:22] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 32 bytes [Feb 27 10:19:22] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.136:61145' into... [Feb 27 10:19:22] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.136' and port '61145'. [Feb 27 10:19:22] DEBUG[4242]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254:13763' into... [Feb 27 10:19:22] DEBUG[4242]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port '13763'. [Feb 27 10:19:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:23] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:23] DEBUG[6396]: chan_sip.c:9409 __find_call: = Looking for Call ID: uuk02d0iacl2qct7vfia (Checking From) --From tag m8as2t5dj3 --To-tag as067d1913 [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: chan_sip.c:28642 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: chan_sip.c:3409 sip_alreadygone: Setting SIP_ALREADYGONE on dialog uuk02d0iacl2qct7vfia [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: chan_sip.c:27249 handle_request_bye: Received bye, issuing owner hangup [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: 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:19:23] DEBUG[6396][C-000000ad]: res_http_websocket.c:1420 __ast_websocket_write_string: Writing websocket string of length 427 [Feb 27 10:19:23] DEBUG[6396][C-000000ad]: res_http_websocket.c:354 __ast_websocket_write: Writing websocket text frame, length 427 [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x2cf8120(SIP/1099-00000030) state from:0 to:1 [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: pulling 0x2cf8120(SIP/1099-00000030) [Feb 27 10:19:23] -- Channel SIP/1099-00000030 left 'simple_bridge' basic-bridge <3a618386-e0e9-4953-9dbe-ce702f562282> [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x2cf8120(SIP/1099-00000030) is leaving simple_bridge technology [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge.c:322 bridge_dissolve: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: dissolving bridge with cause 16(Normal Clearing) [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x370bab0(Khomp/B0C30-0.0) state from:0 to:2 [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge.c:283 bridge_queue_action_nodup: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: queueing action type:13 sub:1001 [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: bridge.c:1003 smart_bridge_operation: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282 is dissolved, not performing smart bridge operation. [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: app_dial.c:3229 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:4346 __ast_pbx_run: Spawn extension (locales,9123,21) exited non-zero on 'SIP/1099-00000030' [Feb 27 10:19:23] == Spawn extension (locales, 9123, 21) exited non-zero on 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALDIALED' is '123' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'select rates.gateway, rates.rate, rates.cost, rates.note FROM rates LEFT JOIN provider ON provider.name=rates.gateway WHERE provider.status = 'true' AND substring( '123', 1, length( prefix_regexp ) ) REGEXP prefix_regexp ORDER BY length(prefix_regexp) DESC,rates.rate ASC' [Feb 27 10:19:23] DEBUG[4150]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/1099-00000030 - start 1488201556.834863 answer 1488201562.414764 end 1488201563.872974 dispo ANSWERED [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Cause: 16 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: 9123 Priority: 21 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Cause: 16 [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: pulling 0x370bab0(Khomp/B0C30-0.0) [Feb 27 10:19:23] -- Channel Khomp/B0C30-0.0 left 'simple_bridge' basic-bridge <3a618386-e0e9-4953-9dbe-ce702f562282> [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: 0x370bab0(Khomp/B0C30-0.0) is leaving simple_bridge technology [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge.c:1003 smart_bridge_operation: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282 is dissolved, not performing smart bridge operation. [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge.c:648 destroy_bridge: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: actually destroying basic bridge, nobody wants it anymore [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge.c:673 destroy_bridge: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: calling basic bridge destructor [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge.c:679 destroy_bridge: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: calling simple_bridge technology stop [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: bridge.c:686 destroy_bridge: Bridge 3a618386-e0e9-4953-9dbe-ce702f562282: calling simple_bridge technology destructor [Feb 27 10:19:23] DEBUG[7943][C-000000ad]: channel.c:2728 ast_hangup: Hanging up channel 'Khomp/B0C30-0.0' [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Khomp - B0C30 [Feb 27 10:19:23] DEBUG[4150]: cdr.c:1121 cdr_object_create_public_records: CDR for Khomp/B0C30-0.0 is dialed and has no Party B; discarding [Feb 27 10:19:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none Channel: Khomp/B0C30-0.0 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 3a618386-e0e9-4953-9dbe-ce702f562282 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: Khomp/B0C30-0.0 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 9123 CallerIDName: ConnectedLineNum: 1099 ConnectedLineName: Language: en AccountCode: Integra Context: entrantes-00-30 Exten: Priority: 1 Uniqueid: 1488201556.111 Linkedid: 1488201556.110 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for Khomp/B0C30 - state 1 (Not in use) [Feb 27 10:19:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:19:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:23] DEBUG[4247]: app_queue.c:2503 device_state_cb: Device 'Khomp/B0C30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Khomp/B0C30 State: NOT_INUSE [Feb 27 10:19:23] > Found no rows [select rates.gateway, rates.rate, rates.cost, rates.note FROM rates LEFT JOIN provider ON provider.name=rates.gateway WHERE provider.status = 'true' AND substring( '123', 1, length( prefix_regexp ) ) REGEXP prefix_regexp ORDER BY length(prefix_regexp) DESC,rates.rate ASC] [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function ODBC_Data(select rates.gateway\, rates.rate\, rates.cost\, rates.note FROM rates LEFT JOIN provider ON provider.name=rates.gateway WHERE provider.status = 'true' AND substring( '123'\, 1\, length( prefix_regexp ) ) REGEXP prefix_regexp ORDER BY length(prefix_regexp) DESC\,rates.rate ASC) result is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:1] Set("SIP/1099-00000030", "HASH(rates)=") in new stack [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: HASH(rates)= [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 1 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: HASH(rates)= [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(billsec) result is '1' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function MATH(1 / 60,f) result is '0.016667' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:2] Set("SIP/1099-00000030", "talkedminutes=0.016667") in new stack [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'talkedminutes' is '0.016667' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:3] Set("SIP/1099-00000030", "talkedminutes=1") in new stack [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'talkedminutes' is '1' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(rates,rate) result is '' [Feb 27 10:19:23] WARNING[7938][C-000000ad]: func_math.c:269 math: ' ' is not a valid number [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function MATH(1 * ,f) result is '(null)' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:4] Set("SIP/1099-00000030", "chargedbalance=") in new stack [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'talkedminutes' is '1' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(rates,cost) result is '' [Feb 27 10:19:23] WARNING[7938][C-000000ad]: func_math.c:269 math: ' ' is not a valid number [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function MATH(1 * ,f) result is '(null)' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:5] Set("SIP/1099-00000030", "realbalance=") in new stack [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'chargedbalance' is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:6] Set("SIP/1099-00000030", "CDR(charged_balance)=") in new stack [Feb 27 10:19:23] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 2 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: talkedminutes=0.016667 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 3 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: talkedminutes=1 [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 2 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: talkedminutes=0.016667 [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 3 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: talkedminutes=1 [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 4 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: chargedbalance= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 4 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: chargedbalance= [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 5 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: realbalance= [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 6 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(charged_balance)= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 5 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: realbalance= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 6 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(charged_balance)= [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'realbalance' is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:7] Set("SIP/1099-00000030", "CDR(real_balance)=") in new stack [Feb 27 10:19:23] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 7 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(real_balance)= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 7 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(real_balance)= [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(rates,note) result is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:8] Set("SIP/1099-00000030", "CDR(note)=") in new stack [Feb 27 10:19:23] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 8 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(note)= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 8 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(note)= [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function HASH(rates,gateway) result is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:9] Set("SIP/1099-00000030", "CDR(carrier)=") in new stack [Feb 27 10:19:23] WARNING[4150]: func_cdr.c:383 cdr_write_callback: CDR requires a value (CDR(variable)=value) [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 9 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(carrier)= [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 9 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(carrier)= [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:10] Set("SIP/1099-00000030", "CDR(userfield)=test") in new stack [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 10 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(userfield)=test [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 10 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(userfield)=test [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'Set' [Feb 27 10:19:23] -- Executing [h@locales:11] Set("SIP/1099-00000030", "CDR(accountcode)=test") in new stack [Feb 27 10:19:23] WARNING[4150]: func_cdr.c:395 cdr_write_callback: Using the CDR function to set 'accountcode' is deprecated. Please use the CHANNEL function instead. [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(accountcode)=test [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 OldAccountCode: Integra [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: Integra Context: locales Exten: h Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: Set AppData: CDR(accountcode)=test [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 11 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 OldAccountCode: Integra [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTQUEUE' is '' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1488201556.110' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AGENT' is 'Integra' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '1' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIALEDTIME' is '7' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIALED' is '9123' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'IdLlamada' is NULL [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:2875 pbx_extension_helper: Launching 'QueueUpdate' [Feb 27 10:19:23] -- Executing [h@locales:12] QueueUpdate("SIP/1099-00000030", ",1488201556.110,Integra,ANSWER,1,7|9123||") in new stack [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: QueueUpdate AppData: ,1488201556.110,Integra,ANSWER,1,7|9123|| [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Extension: h Application: QueueUpdate AppData: ,1488201556.110,Integra,ANSWER,1,7|9123|| [Feb 27 10:19:23] WARNING[7938][C-000000ad]: app_queue.c:10608 qupd_exec: Missing argument to UpdateQueue (queuename,uniqueid,membername,status,talktime,params[totaltime|callednumber]) [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: pbx.c:4157 ast_pbx_h_exten_run: Spawn extension (locales,h,12) exited non-zero on 'SIP/1099-00000030' [Feb 27 10:19:23] == Spawn extension (locales, h, 12) exited non-zero on 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: abstract_jb.c:885 hook_destroy_cb: JITTERBUFFER hook destroyed [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: channel.c:2728 ast_hangup: Hanging up channel 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: chan_sip.c:7154 sip_hangup: Hangup call SIP/1099-00000030, SIP callid uuk02d0iacl2qct7vfia [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:19:23] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 1 (Not in use) [Feb 27 10:19:23] 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:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/1099 State: NOT_INUSE [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x37c2c90' [Feb 27 10:19:23] DEBUG[4255]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:19:23] DEBUG[4256]: manager.c:5861 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/1099-00000030 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1099 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: es AccountCode: test Context: locales Exten: h Priority: 12 Uniqueid: 1488201556.110 Linkedid: 1488201556.110 Cause: 16 Cause-txt: Normal Clearing [Feb 27 10:19:23] DEBUG[4150]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fbfa000f150 from class 'RESData' [Feb 27 10:19:23] DEBUG[4150]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,guid,linkedid,peeraccount,sequence) VALUES ({ ts '2017-02-27 10:19:16' },'"" <1099>','1099','9123','locales','SIP/1099-00000030','Khomp/B0C30-0.0','Dial','Khomp/B0C30/123,60,TtKk,',7,1,'ANSWERED',3,'Integra','1488201556.110','c1ebcb80-87ff-4efc-971a-eb8680a7400a','1488201556.110','Integra',89)] [Feb 27 10:19:23] DEBUG[7938][C-000000ad]: abstract_jb.c:875 datastore_destroy_cb: JITTERBUFFER datastore destroyed [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 1099 [Feb 27 10:19:23] DEBUG[4146]: chan_sip.c:30168 sip_devicestate: Checking device state for peer 1099 [Feb 27 10:19:23] DEBUG[4146]: devicestate.c:474 do_state_change: Changing state for SIP/1099 - state 1 (Not in use) [Feb 27 10:19:23] DEBUG[4150]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7fbfa000f150 into pool [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(start) result is '2017-02-27 10:19:16' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(2017-02-27 10:19:16) result is '"2017-02-27 10:19:16"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(clid)' (from 'CDR(clid)})' len 9) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(clid) result is '"" <1099>' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE("" <1099>) result is '""""" <1099>"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(src) result is '1099' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1099) result is '"1099"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dst) result is '9123' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(9123) result is '"9123"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dcontext) result is 'locales' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(locales) result is '"locales"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(channel) result is 'SIP/1099-00000030' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(SIP/1099-00000030) result is '"SIP/1099-00000030"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dstchannel) result is 'Khomp/B0C30-0.0' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Khomp/B0C30-0.0) result is '"Khomp/B0C30-0.0"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(lastapp) result is 'Dial' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Dial) result is '"Dial"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(lastdata) result is 'Khomp/B0C30/123,60,TtKk,' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Khomp/B0C30/123,60,TtKk,) result is '"Khomp/B0C30/123,60,TtKk,"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(duration)' (from 'CDR(duration)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(duration) result is '7' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(7) result is '"7"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(billsec)' (from 'CDR(billsec)})' len 12) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(billsec) result is '1' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1) result is '"1"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(disposition) result is 'ANSWERED' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(ANSWERED) result is '"ANSWERED"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(amaflags) result is 'DOCUMENTATION' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(accountcode) result is 'Integra' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(Integra) result is '"Integra"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(userfield) result is '' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(uniqueid) result is '1488201556.110' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(1488201556.110) result is '"1488201556.110"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(type)' (from 'CDR(type)})' len 9) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(type) result is '' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(guid)' (from 'CDR(guid)})' len 9) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(guid) result is 'c1ebcb80-87ff-4efc-971a-eb8680a7400a' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE(c1ebcb80-87ff-4efc-971a-eb8680a7400a) result is '"c1ebcb80-87ff-4efc-971a-eb8680a7400a"' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(causecode)' (from 'CDR(causecode)})' len 14) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(causecode) result is '' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(campaign)' (from 'CDR(campaign)})' len 13) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(campaign) result is '' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(sequence) result is '89' [Feb 27 10:19:23] 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:19:23] DEBUG[4150]: pbx_variables.c:474 ast_str_substitute_variables_full: Evaluating 'CDR(dialerbase)' (from 'CDR(dialerbase)})' len 15) [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(dialerbase) result is '' [Feb 27 10:19:23] DEBUG[4150]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CSV_QUOTE() result is '""' [Feb 27 10:19:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:24] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:24] DEBUG[4202]: chan_sip.c:9409 __find_call: = Looking for Call ID: 77ed6c025478b8914f96145a7899c8c5@192.168.99.250:5060 (Checking From) --From tag as0763a782 --To-tag [Feb 27 10:19: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:19:24] DEBUG[4202]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.99.254:5060 [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.250:5060' into... [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.250' and port '5060'. [Feb 27 10:19:24] DEBUG[4202]: chan_sip.c:8996 __sip_alloc: Allocating new SIP dialog for 77ed6c025478b8914f96145a7899c8c5@192.168.99.250:5060 - OPTIONS (No RTP) [Feb 27 10:19:24] DEBUG[4202]: chan_sip.c:28642 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.254' into... [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.254' and port ''. [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.99.250' into... [Feb 27 10:19:24] DEBUG[4202]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.99.250' and port ''. [Feb 27 10:19: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:19:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:25] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus' [Feb 27 10:19:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'Status' [Feb 27 10:19:26] DEBUG[4256]: manager.c:6317 process_message: Running action 'CoreShowChannels' [Feb 27 10:19:26] DEBUG[4202]: chan_sip.c:4361 __sip_autodestruct: Auto destroying SIP dialog '7843d1d23f67277739acf9e103ca44f2@192.168.99.250:5060' [Feb 27 10:19:26] DEBUG[4202]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 7843d1d23f67277739acf9e103ca44f2@192.168.99.250:5060 [Feb 27 10:19:27] DEBUG[4256]: manager.c:6317 process_message: Running action 'QueueStatus'