[Oct 26 09:32:03] VERBOSE[21859] config.c: [Oct 26 09:32:03] == Parsing '/etc/asterisk/logger.conf': [Oct 26 09:32:03] DEBUG[21859] config.c: Parsing /etc/asterisk/logger.conf [Oct 26 09:32:03] VERBOSE[21859] config.c: [Oct 26 09:32:03] == Found [Oct 26 09:32:31] VERBOSE[21720] chan_iax2.c: [Oct 26 09:32:31] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Oct 26 09:32:31] VERBOSE[21720] chan_iax2.c: [Oct 26 09:32:31] Timestamp: 00003ms SCall: 00001 DCall: 00000 [192.168.250.101:4569] [Oct 26 09:32:31] VERBOSE[21720] chan_iax2.c: [Oct 26 09:32:31] USERNAME : 3701 [Oct 26 09:32:31] VERBOSE[21720] chan_iax2.c: [Oct 26 09:32:31] REFRESH : 3600 [Oct 26 09:32:31] VERBOSE[21720] chan_iax2.c: [Oct 26 09:32:31] [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21720] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21720] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21720] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21720] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21720] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: Determining if address 192.168.250.101 with username 3701 requires calltoken validation. Optional = 0 calltoken_required = 2 [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE ipaddr = '192.168.250.101' AND port = '4569' [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: ip callno count incremented to 1 for 192.168.250.101 [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: New max nontrunk callno is 7500 [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: Creating new call structure 7499 [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: Received packet 0, (6, 13) [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: IAX subclass 13 received [Oct 26 09:32:31] DEBUG[21720] chan_iax2.c: For call=7499, set last=3 [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21720] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21720] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21720] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21720] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21720] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21710] devicestate.c: No provider found, checking channel drivers for IAX2 - 3701 [Oct 26 09:32:31] DEBUG[21710] chan_iax2.c: Checking device state for device 3701 [Oct 26 09:32:31] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21710] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21710] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21710] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21710] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21710] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21710] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3701? addr=0, defaddr=0 maxms=0, lastms=0 [Oct 26 09:32:31] DEBUG[21710] devicestate.c: Changing state for IAX2/3701 - state 5 (Unavailable) [Oct 26 09:32:31] DEBUG[21710] devicestate.c: device 'IAX2/3701' state '5' [Oct 26 09:32:31] DEBUG[21745] app_queue.c: Device 'IAX2/3701' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21720] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21720] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21720] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21720] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21720] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21718] chan_iax2.c: Sending 1 on 7499/1 to 192.168.250.101:4569 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] Timestamp: 00001ms SCall: 07499 DCall: 00001 [192.168.250.101:4569] [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] AUTHMETHODS : 3 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] CHALLENGE : \x35\x30\x36\x31\x31\x32\x36\x34\x36 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] USERNAME : 3701 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] Timestamp: 00477ms SCall: 00001 DCall: 07499 [192.168.250.101:4569] [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] USERNAME : 3701 [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] MD5 RESULT : c9450a8fba03fdeebf64fd3e711fc521 [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: Received packet 1, (6, 13) [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: Cancelling transmission of packet 0 [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: IAX subclass 13 received [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: For call=7499, set last=477 [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21721] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21721] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21721] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21721] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21721] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21710] devicestate.c: No provider found, checking channel drivers for IAX2 - 3701 [Oct 26 09:32:31] DEBUG[21710] chan_iax2.c: Checking device state for device 3701 [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:31] DEBUG[21710] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21710] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21710] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21710] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21710] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21710] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3701? addr=0, defaddr=0 maxms=0, lastms=0 [Oct 26 09:32:31] DEBUG[21710] devicestate.c: Changing state for IAX2/3701 - state 5 (Unavailable) [Oct 26 09:32:31] DEBUG[21710] devicestate.c: device 'IAX2/3701' state '5' [Oct 26 09:32:31] DEBUG[21745] app_queue.c: Device 'IAX2/3701' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 26 09:32:31] DEBUG[21721] netsock2.c: Splitting '' gives... [Oct 26 09:32:31] DEBUG[21721] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:31] ERROR[21721] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:31] WARNING[21721] acl.c: Unable to lookup '' [Oct 26 09:32:31] WARNING[21721] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE ast_iax SET ipaddr = '192.168.250.101', port = '4569', regseconds = '1288092751' WHERE name = '3701' [Oct 26 09:32:31] DEBUG[21721] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: ast_iax [Oct 26 09:32:31] ERROR[21721] chan_iax2.c: Bad address cast to IPv4 [Oct 26 09:32:31] DEBUG[21718] chan_iax2.c: Sending 460 on 7499/1 to 192.168.250.101:4569 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] Timestamp: 00460ms SCall: 07499 DCall: 00001 [192.168.250.101:4569] [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] USERNAME : 3701 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] DATE TIME : 2010-10-26 09:32:30 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] REFRESH : 1800 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] APPARENT ADDRES : IPV4 0.0.0.0:0 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] CALLING NUMBER : 3701 [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] CALLING NAME : Teste IAX [Oct 26 09:32:31] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:31] [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Oct 26 09:32:31] VERBOSE[21721] chan_iax2.c: [Oct 26 09:32:31] Timestamp: 00460ms SCall: 00001 DCall: 07499 [192.168.250.101:4569] [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: Received packet 2, (6, 4) [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: Cancelling transmission of packet 1 [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: Really destroying 7499, having been acked on final message [Oct 26 09:32:31] DEBUG[21721] chan_iax2.c: schedule decrement of callno used for 192.168.250.101 in 60 seconds [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00003ms SCall: 00002 DCall: 00000 [192.168.250.101:4569] [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] VERSION : 2 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLING NUMBER : 3701 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLING NAME : Teste [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLING PRESNTN : 1 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLING TYPEOFN : 16 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLING TRANSIT : 0 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] FORMAT : 8 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CAPABILITY : 1550 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] USERNAME : 3701 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] CALLED NUMBER : 04730565620 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] DNID : 04730565620 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] ADSICPE : 0 [Oct 26 09:32:44] VERBOSE[21725] chan_iax2.c: [Oct 26 09:32:44] [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: Determining if address 192.168.250.101 with username 3701 requires calltoken validation. Optional = 0 calltoken_required = 2 [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE ipaddr = '192.168.250.101' AND port = '4569' [Oct 26 09:32:44] DEBUG[21725] netsock2.c: Splitting '' gives... [Oct 26 09:32:44] DEBUG[21725] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:44] ERROR[21725] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:44] WARNING[21725] acl.c: Unable to lookup '' [Oct 26 09:32:44] WARNING[21725] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: ip callno count incremented to 2 for 192.168.250.101 [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: New max nontrunk callno is 251 [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: Creating new call structure 250 [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: Received packet 0, (6, 1) [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: IAX subclass 1 received [Oct 26 09:32:44] DEBUG[21725] chan_iax2.c: For call=250, set last=3 [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'ddi' AND priority = '1' [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'ddi' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'blacklist' AND priority = '1' [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'blacklist' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'abreviados' AND priority = '1' [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'abreviados' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'dddfix' AND priority = '1' [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21725] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'dddfix' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21718] chan_iax2.c: Sending 7 on 250/2 to 192.168.250.101:4569 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00007ms SCall: 00250 DCall: 00002 [192.168.250.101:4569] [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] AUTHMETHODS : 3 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] CHALLENGE : \x34\x35\x35\x33\x30\x31\x34\x37\x36 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] USERNAME : 3701 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] [Oct 26 09:32:44] VERBOSE[21726] chan_iax2.c: [Oct 26 09:32:44] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP [Oct 26 09:32:44] VERBOSE[21726] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00011ms SCall: 00002 DCall: 00250 [192.168.250.101:4569] [Oct 26 09:32:44] VERBOSE[21726] chan_iax2.c: [Oct 26 09:32:44] MD5 RESULT : 313ee1056532dd287f1fc8a47d5fd949 [Oct 26 09:32:44] VERBOSE[21726] chan_iax2.c: [Oct 26 09:32:44] [Oct 26 09:32:44] DEBUG[21726] chan_iax2.c: Received packet 1, (6, 9) [Oct 26 09:32:44] DEBUG[21726] chan_iax2.c: Cancelling transmission of packet 0 [Oct 26 09:32:44] DEBUG[21726] chan_iax2.c: IAX subclass 9 received [Oct 26 09:32:44] DEBUG[21726] chan_iax2.c: For call=250, set last=11 [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'ddi' AND priority = '1' [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'ddi' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'blacklist' AND priority = '1' [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'blacklist' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'abreviados' AND priority = '1' [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'abreviados' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'dddfix' AND priority = '1' [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21726] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'dddfix' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] VERBOSE[21726] chan_iax2.c: [Oct 26 09:32:44] -- Accepting AUTHENTICATED call from 192.168.250.101: > requested format = alaw, > requested prefs = (), > actual format = alaw, > host prefs = (alaw), > priority = mine [Oct 26 09:32:44] DEBUG[21718] chan_iax2.c: Sending 13 on 250/2 to 192.168.250.101:4569 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00013ms SCall: 00250 DCall: 00002 [192.168.250.101:4569] [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] FORMAT : 8 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] FORMAT2 : alaw [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] [Oct 26 09:32:44] VERBOSE[21727] chan_iax2.c: [Oct 26 09:32:44] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Oct 26 09:32:44] VERBOSE[21727] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00013ms SCall: 00002 DCall: 00250 [192.168.250.101:4569] [Oct 26 09:32:44] DEBUG[21727] chan_iax2.c: Received packet 2, (6, 4) [Oct 26 09:32:44] DEBUG[21727] chan_iax2.c: Cancelling transmission of packet 1 [Oct 26 09:32:44] DEBUG[21727] chan_iax2.c: IAX subclass 4 received [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'ddi' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'ddi' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'blacklist' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'blacklist' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'abreviados' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'abreviados' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'dddfix' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'dddfix' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'ddi' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'ddi' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'blacklist' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'blacklist' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'abreviados' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'abreviados' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'dddfix' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'dddfix' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten = '04730565620' AND context = 'dddfix' AND priority = '1' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_extensions WHERE exten LIKE '\\_%' AND context = 'dddfix' AND priority = '1' ORDER BY exten [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'EXTEN' is '04730565620' [Oct 26 09:32:44] VERBOSE[21860] pbx_realtime.c: [Oct 26 09:32:44] -- Executing [04730565620@podeddi:1] Gosub("IAX2/3701-250", "externas,s,1(4730565620,IAX2/IAXPROVIDER,/55,,,DAHDI/g1,/021,30,kKt,0,2,0,1)") [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Channel IAX2/3701-250 has no datastore, so we're allocating one. [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG1' to '4730565620' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG2' to 'IAX2/IAXPROVIDER' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG3' to '/55' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG4' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG5' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG6' to 'DAHDI/g1' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG7' to '/021' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG8' to '30' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG9' to 'kKt' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG10' to '0' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG11' to '2' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG12' to '0' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG13' to '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG1' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:1] MSet("IAX2/3701-250", "LOCAL(DESTINO)=4730565620") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG2' is 'IAX2/IAXPROVIDER' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:2] MSet("IAX2/3701-250", "LOCAL(TERMINACAO1)=IAX2/IAXPROVIDER") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG3' is '/55' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:3] MSet("IAX2/3701-250", "LOCAL(PREFIXO1)=/55") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG4' is '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:4] MSet("IAX2/3701-250", "LOCAL(TERMINACAO2)=") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG5' is '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:5] MSet("IAX2/3701-250", "LOCAL(PREFIXO2)=") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG6' is 'DAHDI/g1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:6] MSet("IAX2/3701-250", "LOCAL(TERMINACAO3)=DAHDI/g1") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG7' is '/021' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:7] MSet("IAX2/3701-250", "LOCAL(PREFIXO3)=/021") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG8' is '30' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:8] MSet("IAX2/3701-250", "LOCAL(TEMPORING)=30") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG9' is 'kKt' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:9] MSet("IAX2/3701-250", "LOCAL(OPCAODIAL)=kKt") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG10' is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:10] MSet("IAX2/3701-250", "LOCAL(GRAVACHAMADA)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG11' is '2' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:11] MSet("IAX2/3701-250", "LOCAL(C_ID_TRUNK1)=2") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG12' is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:12] MSet("IAX2/3701-250", "LOCAL(C_ID_TRUNK2)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG13' is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:13] MSet("IAX2/3701-250", "LOCAL(C_ID_TRUNK3)=1") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '3701' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:14] Set("IAX2/3701-250", "ORIGEM=3701") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DESTINO' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:15] Set("IAX2/3701-250", "CDR(c_dst)=4730565620") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'CHANNEL' is 'IAX2/3701-250' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:16] GotoIf("IAX2/3701-250", "0?17:19") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,19) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:19] Set("IAX2/3701-250", "FAMILIA=iaxpeers") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:20] NoOp("IAX2/3701-250", "Finish if_externas_29") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:21] NoOp("IAX2/3701-250", "***** ORIGINADOR *****") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'FAMILIA' is 'iaxpeers' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ORIGEM' is '3701' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing id to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing name to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing type to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing username to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mailbox to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing secret to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing dbsecret to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing context to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regcontext to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing host to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing ipaddr to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing port to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing defaultip to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sourceaddress to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mask to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regexten to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regseconds to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing accountcode to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohinterpret to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohsuggest to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing inkeys to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing outkeys to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing language to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callerid to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing cid_number to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sendani to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing fullname to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callgroup to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing pickupgroup to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing trunk to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing auth to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing maxauthreq to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing requirecalltoken to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing encryption to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing transfer to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing jitterbuffer to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing forcejitterbuffer to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing disallow to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing allow to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing codecpriority to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualify to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifysmoothing to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqok to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqnotok to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing timezone to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing adsi to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing amaflags to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing setvar to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing deny to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing permit to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing useragent to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_exten to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_prefix to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_nome to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_classeusuario to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaincondicional to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaocupado to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_siganaoatende to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_naoperturbe to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_tempochamada to c_tempochamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Match! Value is 600 [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '600' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:22] Set("IAX2/3701-250", "TEMPOCHAMADA=600") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'FAMILIA' is 'iaxpeers' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ORIGEM' is '3701' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing id to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing name to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing type to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing username to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mailbox to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing secret to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing dbsecret to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing context to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regcontext to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing host to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing ipaddr to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing port to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing defaultip to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sourceaddress to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mask to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regexten to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regseconds to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing accountcode to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohinterpret to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohsuggest to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing inkeys to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing outkeys to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing language to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callerid to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing cid_number to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sendani to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing fullname to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callgroup to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing pickupgroup to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing trunk to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing auth to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing maxauthreq to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing requirecalltoken to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing encryption to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing transfer to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing jitterbuffer to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing forcejitterbuffer to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing disallow to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing allow to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing codecpriority to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualify to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifysmoothing to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqok to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqnotok to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing timezone to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing adsi to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing amaflags to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing setvar to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing deny to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing permit to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing useragent to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_exten to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_prefix to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_nome to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_classeusuario to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaincondicional to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaocupado to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_siganaoatende to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_naoperturbe to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_tempochamada to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_temporing to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_cadeadoeletronico to c_cadeadoeletronico [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Match! Value is 0 [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:23] Set("IAX2/3701-250", "CADEADO=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'FAMILIA' is 'iaxpeers' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ORIGEM' is '3701' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing id to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing name to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing type to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing username to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mailbox to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing secret to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing dbsecret to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing context to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regcontext to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing host to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing ipaddr to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing port to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing defaultip to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sourceaddress to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mask to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regexten to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing regseconds to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing accountcode to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohinterpret to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing mohsuggest to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing inkeys to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing outkeys to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing language to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callerid to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing cid_number to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing sendani to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing fullname to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing callgroup to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing pickupgroup to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing trunk to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing auth to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing maxauthreq to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing requirecalltoken to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing encryption to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing transfer to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing jitterbuffer to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing forcejitterbuffer to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing disallow to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing allow to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing codecpriority to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualify to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifysmoothing to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqok to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing qualifyfreqnotok to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing timezone to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing adsi to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing amaflags to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing setvar to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing deny to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing permit to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing useragent to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_exten to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_prefix to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_nome to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_classeusuario to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaincondicional to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_sigaocupado to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_siganaoatende to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_naoperturbe to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_tempochamada to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_temporing to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_cadeadoeletronico to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Comparing c_gravachamada to c_gravachamada [Oct 26 09:32:44] DEBUG[21860] func_realtime.c: Match! Value is 1 [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:24] Set("IAX2/3701-250", "GRAVACHAMADA=1") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'TEMPOCHAMADA' is '600' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:25] GotoIf("IAX2/3701-250", "1?26:27") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,26) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'OPCDIAL' is NULL [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'TEMPOCHAMADA' is '600' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:26] Set("IAX2/3701-250", "OPCAODIAL=S(600)") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:27] NoOp("IAX2/3701-250", "Finish if_externas_30") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'CADEADO' is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:28] GotoIf("IAX2/3701-250", "0?29:32") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,32) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:32] NoOp("IAX2/3701-250", "Finish if_externas_31") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'GRAVACHAMADA' is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:33] GotoIf("IAX2/3701-250", "1?34:35") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,34) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ORIGEM' is '3701' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DESTINO' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Gosub' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:34] Gosub("IAX2/3701-250", "gravachamada,s,1(3701,4730565620,S)") in new stack [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG1' to '3701' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG2' to '4730565620' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG3' to 'S' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG4' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG5' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG6' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG7' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG8' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG9' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG10' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG11' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG12' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG13' to '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG1' is '3701' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:1] MSet("IAX2/3701-250", "LOCAL(ORIGEM)=3701") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG2' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:2] MSet("IAX2/3701-250", "LOCAL(DESTINO)=4730565620") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ARG3' is 'S' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MSet' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:3] MSet("IAX2/3701-250", "LOCAL(PREFIXO)=S") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'EPOCH' is '1288092764' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '2010/10/26' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:4] Set("IAX2/3701-250", "PASTAARQUIVO=2010/10/26") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'PREFIXO' is 'S' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'ORIGEM' is '3701' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'EPOCH' is '1288092764' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '20101026-093244' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DESTINO' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:5] Set("IAX2/3701-250", "NOMEARQUIVO=S-3701-20101026-093244-4730565620.WAV") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'PASTAARQUIVO' is '2010/10/26' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'NOMEARQUIVO' is 'S-3701-20101026-093244-4730565620.WAV' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:6] Set("IAX2/3701-250", "MIXMONITOR_FILENAME=2010/10/26/S-3701-20101026-093244-4730565620.WAV") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'NOMEARQUIVO' is 'S-3701-20101026-093244-4730565620.WAV' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:7] Set("IAX2/3701-250", "CDR(userfield)=S-3701-20101026-093244-4730565620.WAV") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:8] Set("IAX2/3701-250", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack [Oct 26 09:32:44] DEBUG[21860] func_audiohookinherit.c: Set audiohook MixMonitor to be inheritable [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'MIXMONITOR_FILENAME' is '2010/10/26/S-3701-20101026-093244-4730565620.WAV' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'MixMonitor' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:9] MixMonitor("IAX2/3701-250", "2010/10/26/S-3701-20101026-093244-4730565620.WAV,b") in new stack [Oct 26 09:32:44] DEBUG[21860] autochan.c: Created autochan 0xbc3c770 to hold channel IAX2/3701-250 (0xbadfd78) [Oct 26 09:32:44] VERBOSE[21861] app_mixmonitor.c: [Oct 26 09:32:44] == Begin MixMonitor Recording IAX2/3701-250 [Oct 26 09:32:44] DEBUG[21861] audiohook.c: Read factory 0xbc27b10 and write factory 0xbc28538 both fail to provide 160 samples [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Return' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@gravachamada:10] Return("IAX2/3701-250", "") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:35] NoOp("IAX2/3701-250", "Finish if_externas_32") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'C_ID_TRUNK1' is '2' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:36] Set("IAX2/3701-250", "CDR(c_id_trunk1)=2") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'C_ID_TRUNK2' is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:37] Set("IAX2/3701-250", "CDR(c_id_trunk2)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'C_ID_TRUNK3' is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:38] Set("IAX2/3701-250", "CDR(c_id_trunk3)=1") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:39] Set("IAX2/3701-250", "CDR(c_id_trunk)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:40] Set("IAX2/3701-250", "CDR(c_trunk1_s)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:41] Set("IAX2/3701-250", "CDR(c_trunk2_s)=2") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:42] Set("IAX2/3701-250", "CDR(c_trunk3_s)=2") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'C_ID_TRUNK1' is '2' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:43] Set("IAX2/3701-250", "CDR(c_id_trunk)=2") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'TERMINACAO1' is 'IAX2/IAXPROVIDER' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'PREFIXO1' is '/55' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DESTINO' is '4730565620' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'TEMPORING' is '30' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'OPCAODIAL' is 'S(600)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Dial' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:44] Dial("IAX2/3701-250", "IAX2/IAXPROVIDER/554730565620,30,S(600)") in new stack [Oct 26 09:32:44] VERBOSE[21860] app_dial.c: [Oct 26 09:32:44] -- Setting call duration limit to 600.000 seconds. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = 'IAXPROVIDER' AND host = 'dynamic' [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21860] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = 'IAXPROVIDER' [Oct 26 09:32:44] VERBOSE[21860] dnsmgr.c: [Oct 26 09:32:44] > doing dnsmgr_lookup for 'voip.IAXPROVIDER.com.br' [Oct 26 09:32:44] DEBUG[21860] netsock2.c: Splitting 'voip.IAXPROVIDER.com.br' gives... [Oct 26 09:32:44] DEBUG[21860] netsock2.c: ...host 'voip.IAXPROVIDER.com.br' and port '(null)'. [Oct 26 09:32:44] DEBUG[21860] netsock2.c: Splitting '' gives... [Oct 26 09:32:44] DEBUG[21860] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:44] ERROR[21860] netsock2.c: getaddrinfo("", "(null)", ...): ai_family not supported [Oct 26 09:32:44] WARNING[21860] acl.c: Unable to lookup '' [Oct 26 09:32:44] DEBUG[21860] netsock2.c: Splitting 'IAXPROVIDER' gives... [Oct 26 09:32:44] DEBUG[21860] netsock2.c: ...host 'IAXPROVIDER' and port '(null)'. [Oct 26 09:32:44] ERROR[21860] netsock2.c: getaddrinfo("IAXPROVIDER", "(null)", ...): Name or service not known [Oct 26 09:32:44] WARNING[21860] acl.c: Unable to lookup 'IAXPROVIDER' [Oct 26 09:32:44] WARNING[21860] chan_iax2.c: No such host: IAXPROVIDER [Oct 26 09:32:44] WARNING[21860] app_dial.c: Unable to create channel of type 'IAX2' (cause 20 - Unknown) [Oct 26 09:32:44] VERBOSE[21860] app_dial.c: [Oct 26 09:32:44] == Everyone is busy/congested at this time (1:0/0/1) [Oct 26 09:32:44] DEBUG[21860] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:45] GotoIf("IAX2/3701-250", "0?46:49") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,49) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '1' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:49] GotoIf("IAX2/3701-250", "1?50:82") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,50) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:50] Set("IAX2/3701-250", "CDR(c_id_trunk)=0") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:51] Set("IAX2/3701-250", "CDR(c_trunk1_s)=1") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'TERMINACAO2' is '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Expression result is '0' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'GotoIf' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:52] GotoIf("IAX2/3701-250", "0?53:81") in new stack [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Goto (externas,s,81) [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:81] NoOp("IAX2/3701-250", "Finish if_if_if_externas_33_34_35") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:82] NoOp("IAX2/3701-250", "Finish if_if_externas_33_34") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'NoOp' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:83] NoOp("IAX2/3701-250", "Finish if_externas_33") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Hangup' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@externas:84] Hangup("IAX2/3701-250", "") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Spawn extension (externas,s,84) exited non-zero on 'IAX2/3701-250' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] == Spawn extension (externas, s, 84) exited non-zero on 'IAX2/3701-250' [Oct 26 09:32:44] DEBUG[21860] channel.c: Soft-Hanging up channel 'IAX2/3701-250' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Gosub' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [h@externas:1] Gosub("IAX2/3701-250", "extendecdr,s,1") in new stack [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG1' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG2' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG3' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG4' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG5' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG6' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG7' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG8' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG9' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG10' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG11' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG12' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG13' to '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Result of 'HANGUPCAUSE' is '20' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:1] Set("IAX2/3701-250", "CDR(c_hangupcause)=20") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '192.168.250.101' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:2] Set("IAX2/3701-250", "CDR(c_peerip)=192.168.250.101") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'from' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:3] Set("IAX2/3701-250", "CDR(c_sipfrom)=") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'useragent' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:4] Set("IAX2/3701-250", "CDR(c_useragent)=") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is 'alaw' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:5] Set("IAX2/3701-250", "CDR(c_audioreadformat)=alaw") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is 'alaw' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:6] Set("IAX2/3701-250", "CDR(c_audiowriteformat)=alaw") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'rtpqos,audio,local_lostpackets' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:7] Set("IAX2/3701-250", "CDR(c_locallostpackets)=") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'rtpqos,audio,remote_lostpackets' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:8] Set("IAX2/3701-250", "CDR(c_remotelostpackets)=") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'rtpqos,audio,local_jitter' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:9] Set("IAX2/3701-250", "CDR(c_localjitter)=") in new stack [Oct 26 09:32:44] WARNING[21860] func_channel.c: Unknown or unavailable item requested: 'rtpqos,audio,remote_jitter' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Function result is '(null)' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Set' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:10] Set("IAX2/3701-250", "CDR(c_remotejitter)=") in new stack [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Gosub' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@extendecdr:11] Gosub("IAX2/3701-250", "desliga,s,1") in new stack [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG1' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG2' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG3' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG4' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG5' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG6' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG7' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG8' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG9' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG10' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG11' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG12' to '' [Oct 26 09:32:44] DEBUG[21860] app_stack.c: Setting 'ARG13' to '' [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'PlayTones' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@desliga:1] PlayTones("IAX2/3701-250", "congestion") in new stack [Oct 26 09:32:44] DEBUG[21860] channel.c: Set channel IAX2/3701-250 to write format slin [Oct 26 09:32:44] DEBUG[21860] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 26 09:32:44] DEBUG[21860] channel.c: Prodding channel 'IAX2/3701-250' [Oct 26 09:32:44] WARNING[21860] channel.c: Prodding channel 'IAX2/3701-250' failed [Oct 26 09:32:44] DEBUG[21860] pbx.c: Launching 'Wait' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] -- Executing [s@desliga:2] Wait("IAX2/3701-250", "2") in new stack [Oct 26 09:32:44] DEBUG[21860] channel.c: Set channel IAX2/3701-250 to write format alaw [Oct 26 09:32:44] DEBUG[21860] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 26 09:32:44] DEBUG[21860] pbx.c: Spawn extension (desliga,s,2) exited non-zero on 'IAX2/3701-250' [Oct 26 09:32:44] VERBOSE[21860] pbx.c: [Oct 26 09:32:44] == Spawn extension (desliga, s, 2) exited non-zero on 'IAX2/3701-250' [Oct 26 09:32:44] DEBUG[21861] autochan.c: Removed autochan 0xbc3c770 from the list, about to free it [Oct 26 09:32:44] DEBUG[21860] channel.c: Hanging up channel 'IAX2/3701-250' [Oct 26 09:32:44] DEBUG[21860] chan_iax2.c: We're hanging up IAX2/3701-250 now... [Oct 26 09:32:44] DEBUG[21718] chan_iax2.c: Sending 345 on 250/2 to 192.168.250.101:4569 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: HANGUP [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00345ms SCall: 00250 DCall: 00002 [192.168.250.101:4569] [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] CAUSE CODE : 20 [Oct 26 09:32:44] VERBOSE[21718] chan_iax2.c: [Oct 26 09:32:44] [Oct 26 09:32:44] VERBOSE[21860] chan_iax2.c: [Oct 26 09:32:44] -- Hungup 'IAX2/3701-250' [Oct 26 09:32:44] VERBOSE[21861] app_mixmonitor.c: [Oct 26 09:32:44] == End MixMonitor Recording IAX2/3701-250 [Oct 26 09:32:44] DEBUG[21710] devicestate.c: No provider found, checking channel drivers for IAX2 - 3701 [Oct 26 09:32:44] DEBUG[21710] chan_iax2.c: Checking device state for device 3701 [Oct 26 09:32:44] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Connection okay. [Oct 26 09:32:44] DEBUG[21710] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_iax WHERE name = '3701' AND host = 'dynamic' [Oct 26 09:32:44] DEBUG[21710] netsock2.c: Splitting '' gives... [Oct 26 09:32:44] DEBUG[21710] netsock2.c: ...host '' and port '(null)'. [Oct 26 09:32:44] ERROR[21710] netsock2.c: getaddrinfo("", "(null)", ...): Name or service not known [Oct 26 09:32:44] WARNING[21710] acl.c: Unable to lookup '' [Oct 26 09:32:44] WARNING[21710] chan_iax2.c: Non-local or unbound address specified () in sourceaddress for '3701', reverting to default [Oct 26 09:32:44] DEBUG[21710] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 3701? addr=0, defaddr=0 maxms=0, lastms=0 [Oct 26 09:32:44] DEBUG[21710] devicestate.c: Changing state for IAX2/3701 - state 5 (Unavailable) [Oct 26 09:32:44] DEBUG[21710] devicestate.c: device 'IAX2/3701' state '5' [Oct 26 09:32:44] DEBUG[21745] app_queue.c: Device 'IAX2/3701' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 26 09:32:44] VERBOSE[21728] chan_iax2.c: [Oct 26 09:32:44] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK [Oct 26 09:32:44] VERBOSE[21728] chan_iax2.c: [Oct 26 09:32:44] Timestamp: 00345ms SCall: 00002 DCall: 00250 [192.168.250.101:4569] [Oct 26 09:32:44] DEBUG[21728] chan_iax2.c: Received packet 2, (6, 4) [Oct 26 09:32:44] DEBUG[21728] chan_iax2.c: Cancelling transmission of packet 2 [Oct 26 09:32:44] DEBUG[21728] chan_iax2.c: Really destroying 250, having been acked on final message [Oct 26 09:32:44] DEBUG[21728] chan_iax2.c: schedule decrement of callno used for 192.168.250.101 in 60 seconds