######################################################################### Make New Call ######################################################################### Apr 12 19:00:11 VERBOSE[2931]: -- Starting simple switch on 'Zap/3-1' Apr 12 19:00:13 NOTICE[2931]: Got event 2 (Ring/Answered)... Apr 12 19:00:14 DEBUG[2931]: Expression is '1' Apr 12 19:00:14 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?from-pstn-reghours|s|1:") in new stack Apr 12 19:00:14 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,1) Apr 12 19:00:14 DEBUG[2931]: Expression is '0' Apr 12 19:00:14 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?from-pstn-reghours-nofax|s|1:2") in new stack Apr 12 19:00:14 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,2) Apr 12 19:00:14 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:00:14 DEBUG[2931]: Took Zap/3-1 off hook Apr 12 19:00:14 DEBUG[2931]: Enabled echo cancellation on channel 3 Apr 12 19:00:14 DEBUG[2931]: Engaged echo training on channel 3 Apr 12 19:00:14 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "intype=aa_1") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Executing Cut("Zap/3-1", "intype=intype|-|1") in new stack Apr 12 19:00:15 DEBUG[2931]: Expression is '0' Apr 12 19:00:15 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?7:9") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,9) Apr 12 19:00:15 DEBUG[2931]: Expression is '0' Apr 12 19:00:15 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?10:12") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,12) Apr 12 19:00:15 DEBUG[2931]: Expression is '0' Apr 12 19:00:15 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?13:15") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,15) Apr 12 19:00:15 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "aa_1|s|1") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Goto (aa_1,s,1) Apr 12 19:00:15 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: = ANSWER ^^^^^^ ^ Apr 12 19:00:15 DEBUG[2931]: Expression is '0' Apr 12 19:00:15 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4") in new stack Apr 12 19:00:15 DEBUG[2931]: Not taking any branch Apr 12 19:00:15 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:00:15 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:00:16 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "DIR-CONTEXT=general") in new stack Apr 12 19:00:16 VERBOSE[2931]: -- Executing DigitTimeout("Zap/3-1", "3") in new stack Apr 12 19:00:16 VERBOSE[2931]: -- Set Digit Timeout to 3 Apr 12 19:00:16 VERBOSE[2931]: -- Executing ResponseTimeout("Zap/3-1", "7") in new stack Apr 12 19:00:16 VERBOSE[2931]: -- Set Response Timeout to 7 Apr 12 19:00:16 VERBOSE[2931]: -- Executing BackGround("Zap/3-1", "custom/aa_1") in new stack Apr 12 19:00:16 WARNING[2931]: Not a wav file 49 Apr 12 19:00:16 WARNING[2931]: Unable to open fd on /var/lib/asterisk/sounds/custom/aa_1.wav Apr 12 19:00:16 WARNING[2931]: Unable to open custom/aa_1 (format unknown): No such file or directory Apr 12 19:00:16 WARNING[2931]: ast_streamfile failed on Zap/3-1 for custom/aa_1 Apr 12 19:00:23 WARNING[2931]: Timeout, but no rule 't' in context 'aa_1' Apr 12 19:00:23 VERBOSE[2931]: -- Executing Hangup("Zap/3-1", "") in new stack Apr 12 19:00:23 VERBOSE[2931]: == Spawn extension (aa_1, h, 1) exited non-zero on 'Zap/3-1' Apr 12 19:00:23 DEBUG[2931]: cdr_mysql: inserting a CDR record. Apr 12 19:00:23 DEBUG[2931]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-04-12 19:00:14','90594803','90594803','s','aa_1', 'Zap/3-1','','Hangup','',9,9,'ANSWERED',3,'') Apr 12 19:00:23 DEBUG[2931]: Hangup: channel: 3 index = 0, normal = 18, callwait = -1, thirdcall = -1 Apr 12 19:00:23 DEBUG[2931]: disabled echo cancellation on channel 3 Apr 12 19:00:23 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/3-1 Apr 12 19:00:23 DEBUG[2931]: Updated conferencing on 3, with 0 conference users Apr 12 19:00:23 VERBOSE[2931]: -- Hungup 'Zap/3-1' ######################################################################### Make New Call ######################################################################### Apr 12 19:00:35 VERBOSE[2931]: -- Starting simple switch on 'Zap/3-1' Apr 12 19:00:37 NOTICE[2931]: Got event 2 (Ring/Answered)... Apr 12 19:00:38 DEBUG[2931]: Expression is '1' Apr 12 19:00:38 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?from-pstn-reghours|s|1:") in new stack Apr 12 19:00:38 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,1) Apr 12 19:00:38 DEBUG[2931]: Expression is '0' Apr 12 19:00:38 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?from-pstn-reghours-nofax|s|1:2") in new stack Apr 12 19:00:38 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,2) Apr 12 19:00:38 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:00:38 DEBUG[2931]: Took Zap/3-1 off hook Apr 12 19:00:38 DEBUG[2931]: Enabled echo cancellation on channel 3 Apr 12 19:00:38 DEBUG[2931]: Engaged echo training on channel 3 Apr 12 19:00:38 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "intype=aa_1") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Executing Cut("Zap/3-1", "intype=intype|-|1") in new stack Apr 12 19:00:39 DEBUG[2931]: Expression is '0' Apr 12 19:00:39 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?7:9") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,9) Apr 12 19:00:39 DEBUG[2931]: Expression is '0' Apr 12 19:00:39 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?10:12") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,12) Apr 12 19:00:39 DEBUG[2931]: Expression is '0' Apr 12 19:00:39 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?13:15") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,15) Apr 12 19:00:39 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "aa_1|s|1") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Goto (aa_1,s,1) Apr 12 19:00:39 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: = ANSWER ^^^^^^ ^ Apr 12 19:00:39 DEBUG[2931]: Expression is '0' Apr 12 19:00:39 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4") in new stack Apr 12 19:00:39 DEBUG[2931]: Not taking any branch Apr 12 19:00:39 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:00:39 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:00:40 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "DIR-CONTEXT=general") in new stack Apr 12 19:00:40 VERBOSE[2931]: -- Executing DigitTimeout("Zap/3-1", "3") in new stack Apr 12 19:00:40 VERBOSE[2931]: -- Set Digit Timeout to 3 Apr 12 19:00:40 VERBOSE[2931]: -- Executing ResponseTimeout("Zap/3-1", "7") in new stack Apr 12 19:00:40 VERBOSE[2931]: -- Set Response Timeout to 7 Apr 12 19:00:40 VERBOSE[2931]: -- Executing BackGround("Zap/3-1", "custom/aa_1") in new stack Apr 12 19:00:40 WARNING[2931]: Not a wav file 49 Apr 12 19:00:40 WARNING[2931]: Unable to open fd on /var/lib/asterisk/sounds/custom/aa_1.wav Apr 12 19:00:40 WARNING[2931]: Unable to open custom/aa_1 (format unknown): No such file or directory Apr 12 19:00:40 WARNING[2931]: ast_streamfile failed on Zap/3-1 for custom/aa_1 Apr 12 19:00:42 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:00:44 DEBUG[2931]: Auto destroying call '24bdc86bfc3290f7@192.108.130.176' Apr 12 19:00:45 VERBOSE[2931]: == CDR updated on Zap/3-1 Apr 12 19:00:45 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "ext-local|1001|1") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (ext-local,1001,1) Apr 12 19:00:45 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "exten-vm|novm|1001") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "FROMCONTEXT=exten-vm") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "record-enable|1001|IN") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0 > 0?2:4") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-record-enable,s,4) Apr 12 19:00:45 DEBUG[2931]: Expression is '0' Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?5:8") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-record-enable,s,8) Apr 12 19:00:45 DEBUG[2931]: Expression is '0' Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?9:12") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-record-enable,s,12) Apr 12 19:00:45 VERBOSE[2931]: -- Executing DBget("Zap/3-1", "RecEnable=RECORD-IN/1001") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- DBget: varname=RecEnable, family=RECORD-IN, key=1001 Apr 12 19:00:45 VERBOSE[2931]: -- DBget: set variable RecEnable to ENABLED Apr 12 19:00:45 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "CALLFILENAME=20060412-190045-1144882835.24") in new stack Apr 12 19:00:45 DEBUG[2931]: Expression is '1' Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?15:99") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-record-enable,s,15) Apr 12 19:00:45 VERBOSE[2931]: -- Executing Monitor("Zap/3-1", "wav49|20060412-190045-1144882835.24| mb") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "dial|20|tr|1001") in new stack Apr 12 19:00:45 DEBUG[2931]: Expression is '0' Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:2") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-dial,s,2) Apr 12 19:00:45 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: != ^ Apr 12 19:00:45 DEBUG[2931]: Expression is '0' Apr 12 19:00:45 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:3") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Goto (macro-dial,s,3) Apr 12 19:00:45 VERBOSE[2931]: -- Executing SetCIDName("Zap/3-1", "90594803") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Executing AGI("Zap/3-1", "dialparties.agi") in new stack Apr 12 19:00:45 VERBOSE[2931]: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: request = dialparties.agi Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: priority = 4 Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: extension = s Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: language = en Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: accountcode = Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: uniqueid = 1144882835.24 Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: channel = Zap/3-1 Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: callerid = 90594803 <90594803> Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: context = macro-dial Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: type = Zap Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: rdnis = unknown Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: enhanced = 0.0 Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: dnid = unknown Apr 12 19:00:45 VERBOSE[2931]: dialparties.agi: Caller ID name is '90594803' number is '90594803' Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: Added extension 1001 to extension map Apr 12 19:00:45 DEBUG[2931]: Unable to find key '1001' in family 'CF' Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: Extension 1001 cf is disabled Apr 12 19:00:45 DEBUG[2931]: Unable to find key '1001' in family 'DND' Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: Extension 1001 do not disturb is disabled Apr 12 19:00:45 DEBUG[2931]: Manager received command 'Login' Apr 12 19:00:45 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Apr 12 19:00:45 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Found Apr 12 19:00:45 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Apr 12 19:00:45 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Found Apr 12 19:00:45 WARNING[2931]: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 19 of manager_custom.conf Apr 12 19:00:45 DEBUG[2931]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 12 19:00:45 DEBUG[2931]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:00:45 DEBUG[2931]: 192.108.130.166/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:00:45 DEBUG[2931]: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 12 19:00:45 DEBUG[2931]: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 12 19:00:45 DEBUG[2931]: ##### Testing 127.0.0.1 with 192.108.130.0 Apr 12 19:00:45 VERBOSE[2931]: == Manager 'admin' logged on from 127.0.0.1 Apr 12 19:00:45 DEBUG[2931]: Manager received command 'command' Apr 12 19:00:45 DEBUG[2931]: Manager received command '' Apr 12 19:00:45 DEBUG[2931]: Manager received command 'Logoff' Apr 12 19:00:45 VERBOSE[2931]: == Manager 'admin' logged off from 127.0.0.1 Apr 12 19:00:45 DEBUG[2931]: Unable to find key '1001' in family 'CW' Apr 12 19:00:45 VERBOSE[2931]: dialparties.agi: Extension 1001 has call waiting disabled Apr 12 19:00:45 VERBOSE[2931]: -- dialparties.agi: DbSet CALLTRACE/1001 to 90594803 Apr 12 19:00:45 VERBOSE[2931]: dialparties.agi: Dial string is ZAP/1|20|tr Apr 12 19:00:45 VERBOSE[2931]: -- AGI Script dialparties.agi completed, returning 0 Apr 12 19:00:45 VERBOSE[2931]: -- Executing Dial("Zap/3-1", "ZAP/1|20|tr") in new stack Apr 12 19:00:45 DEBUG[2931]: SIMPLE DIAL (NO URL) Apr 12 19:00:45 VERBOSE[2931]: -- Called 1 Apr 12 19:00:45 VERBOSE[2931]: -- Zap/1-1 is ringing Apr 12 19:00:47 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:00:47 DEBUG[2931]: Got event Ringer Off(11) on channel 1 (index 0) Apr 12 19:00:47 VERBOSE[2931]: -- Zap/1-1 is ringing Apr 12 19:00:49 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:00:49 DEBUG[2931]: Got event Ring/Answered(2) on channel 1 (index 0) Apr 12 19:00:49 DEBUG[2931]: Enabled echo cancellation on channel 1 Apr 12 19:00:49 DEBUG[2931]: channel 1 answered Apr 12 19:00:49 DEBUG[2931]: Dropping duplicate answer! Apr 12 19:00:49 VERBOSE[2931]: -- Zap/1-1 answered Zap/3-1 Apr 12 19:00:50 DEBUG[2931]: Auto destroying call 'f17f0bc1a5aac305@192.108.130.177' Apr 12 19:00:51 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:00:51 DEBUG[2931]: Got event On hook(1) on channel 1 (index 0) Apr 12 19:00:51 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:00:51 DEBUG[2931]: Didn't get a frame from channel: Zap/1-1 Apr 12 19:00:51 DEBUG[2931]: Bridge stops bridging channels Zap/3-1 and Zap/1-1 Apr 12 19:00:51 DEBUG[2931]: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1 Apr 12 19:00:51 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:00:51 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/1-1 Apr 12 19:00:51 DEBUG[2931]: Updated conferencing on 1, with 0 conference users Apr 12 19:00:51 VERBOSE[2931]: -- Hungup 'Zap/1-1' Apr 12 19:00:51 DEBUG[2931]: Exiting with DIALSTATUS=ANSWER. Apr 12 19:00:51 VERBOSE[2931]: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/3-1' in macro 'dial' Apr 12 19:00:51 VERBOSE[2931]: == Spawn extension (macro-exten-vm, s, 3) exited non-zero on 'Zap/3-1' in macro 'exten-vm' Apr 12 19:00:51 VERBOSE[2931]: == Spawn extension (ext-local, 1001, 1) exited non-zero on 'Zap/3-1' Apr 12 19:00:51 DEBUG[2931]: cdr_mysql: inserting a CDR record. Apr 12 19:00:51 DEBUG[2931]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-04-12 19:00:38','\"90594803\" <90594803>','90594803','1001','ext-local', 'Zap/3-1','Zap/1-1','Monitor','wav49|20060412-190045-1144882835.24| mX',13,13,'ANSWERED',3,'') Apr 12 19:00:51 DEBUG[2931]: Hangup: channel: 3 index = 0, normal = 18, callwait = -1, thirdcall = -1 Apr 12 19:00:51 DEBUG[2931]: disabled echo cancellation on channel 3 Apr 12 19:00:51 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/3-1 Apr 12 19:00:51 DEBUG[2931]: Updated conferencing on 3, with 0 conference users Apr 12 19:00:51 VERBOSE[2931]: -- Hungup 'Zap/3-1' Apr 12 19:00:51 VERBOSE[2931]: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/20060412-190045-1144882835.24-in.WAV" "/var/spool/asterisk/monitor/20060412-190045-1144882835.24-out.WAV" "/var/spool/asterisk/monitor/20060412-190045-1144882835.24.WAV" && rm -f "/var/spool/asterisk/monitor/20060412-190045-1144882835.24-"* ) & Apr 12 19:00:55 DEBUG[2931]: Message status for 1001@default changed from -1 to 0 on 1 ######################################################################### Make New Call ######################################################################### Apr 12 19:00:59 VERBOSE[2931]: -- Starting simple switch on 'Zap/3-1' Apr 12 19:01:01 NOTICE[2931]: Got event 2 (Ring/Answered)... Apr 12 19:01:02 DEBUG[2931]: Expression is '1' Apr 12 19:01:02 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?from-pstn-reghours|s|1:") in new stack Apr 12 19:01:02 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,1) Apr 12 19:01:02 DEBUG[2931]: Expression is '0' Apr 12 19:01:02 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?from-pstn-reghours-nofax|s|1:2") in new stack Apr 12 19:01:02 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,2) Apr 12 19:01:02 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:01:02 DEBUG[2931]: Took Zap/3-1 off hook Apr 12 19:01:02 DEBUG[2931]: Enabled echo cancellation on channel 3 Apr 12 19:01:02 DEBUG[2931]: Engaged echo training on channel 3 Apr 12 19:01:02 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "intype=aa_1") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Executing Cut("Zap/3-1", "intype=intype|-|1") in new stack Apr 12 19:01:03 DEBUG[2931]: Expression is '0' Apr 12 19:01:03 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?7:9") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,9) Apr 12 19:01:03 DEBUG[2931]: Expression is '0' Apr 12 19:01:03 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?10:12") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,12) Apr 12 19:01:03 DEBUG[2931]: Expression is '0' Apr 12 19:01:03 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?13:15") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,15) Apr 12 19:01:03 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "aa_1|s|1") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Goto (aa_1,s,1) Apr 12 19:01:03 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: = ANSWER ^^^^^^ ^ Apr 12 19:01:03 DEBUG[2931]: Expression is '0' Apr 12 19:01:03 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4") in new stack Apr 12 19:01:03 DEBUG[2931]: Not taking any branch Apr 12 19:01:03 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:01:03 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:01:04 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "DIR-CONTEXT=general") in new stack Apr 12 19:01:04 VERBOSE[2931]: -- Executing DigitTimeout("Zap/3-1", "3") in new stack Apr 12 19:01:04 VERBOSE[2931]: -- Set Digit Timeout to 3 Apr 12 19:01:04 VERBOSE[2931]: -- Executing ResponseTimeout("Zap/3-1", "7") in new stack Apr 12 19:01:04 VERBOSE[2931]: -- Set Response Timeout to 7 Apr 12 19:01:04 VERBOSE[2931]: -- Executing BackGround("Zap/3-1", "custom/aa_1") in new stack Apr 12 19:01:04 WARNING[2931]: Not a wav file 49 Apr 12 19:01:04 WARNING[2931]: Unable to open fd on /var/lib/asterisk/sounds/custom/aa_1.wav Apr 12 19:01:04 WARNING[2931]: Unable to open custom/aa_1 (format unknown): No such file or directory Apr 12 19:01:04 WARNING[2931]: ast_streamfile failed on Zap/3-1 for custom/aa_1 Apr 12 19:01:08 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:01:12 VERBOSE[2931]: == CDR updated on Zap/3-1 Apr 12 19:01:12 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "ext-local|1001|1") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (ext-local,1001,1) Apr 12 19:01:12 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "exten-vm|novm|1001") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "FROMCONTEXT=exten-vm") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "record-enable|1001|IN") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0 > 0?2:4") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-record-enable,s,4) Apr 12 19:01:12 DEBUG[2931]: Expression is '0' Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?5:8") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-record-enable,s,8) Apr 12 19:01:12 DEBUG[2931]: Expression is '0' Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?9:12") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-record-enable,s,12) Apr 12 19:01:12 VERBOSE[2931]: -- Executing DBget("Zap/3-1", "RecEnable=RECORD-IN/1001") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- DBget: varname=RecEnable, family=RECORD-IN, key=1001 Apr 12 19:01:12 VERBOSE[2931]: -- DBget: set variable RecEnable to ENABLED Apr 12 19:01:12 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "CALLFILENAME=20060412-190112-1144882859.26") in new stack Apr 12 19:01:12 DEBUG[2931]: Expression is '1' Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?15:99") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-record-enable,s,15) Apr 12 19:01:12 VERBOSE[2931]: -- Executing Monitor("Zap/3-1", "wav49|20060412-190112-1144882859.26| mb") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "dial|20|tr|1001") in new stack Apr 12 19:01:12 DEBUG[2931]: Expression is '0' Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:2") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-dial,s,2) Apr 12 19:01:12 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: != ^ Apr 12 19:01:12 DEBUG[2931]: Expression is '0' Apr 12 19:01:12 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:3") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Goto (macro-dial,s,3) Apr 12 19:01:12 VERBOSE[2931]: -- Executing SetCIDName("Zap/3-1", "90594803") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Executing AGI("Zap/3-1", "dialparties.agi") in new stack Apr 12 19:01:12 VERBOSE[2931]: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: request = dialparties.agi Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: priority = 4 Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: extension = s Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: language = en Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: accountcode = Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: uniqueid = 1144882859.26 Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: channel = Zap/3-1 Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: callerid = 90594803 <90594803> Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: context = macro-dial Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: type = Zap Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: rdnis = unknown Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: enhanced = 0.0 Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: dnid = unknown Apr 12 19:01:12 VERBOSE[2931]: dialparties.agi: Caller ID name is '90594803' number is '90594803' Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: Added extension 1001 to extension map Apr 12 19:01:12 DEBUG[2931]: Unable to find key '1001' in family 'CF' Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: Extension 1001 cf is disabled Apr 12 19:01:12 DEBUG[2931]: Unable to find key '1001' in family 'DND' Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: Extension 1001 do not disturb is disabled Apr 12 19:01:12 DEBUG[2931]: Manager received command 'Login' Apr 12 19:01:12 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Apr 12 19:01:12 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Found Apr 12 19:01:12 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Apr 12 19:01:12 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Found Apr 12 19:01:12 WARNING[2931]: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 19 of manager_custom.conf Apr 12 19:01:12 DEBUG[2931]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 12 19:01:12 DEBUG[2931]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:01:12 DEBUG[2931]: 192.108.130.166/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:01:12 DEBUG[2931]: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 12 19:01:12 DEBUG[2931]: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 12 19:01:12 DEBUG[2931]: ##### Testing 127.0.0.1 with 192.108.130.0 Apr 12 19:01:12 VERBOSE[2931]: == Manager 'admin' logged on from 127.0.0.1 Apr 12 19:01:12 DEBUG[2931]: Manager received command 'command' Apr 12 19:01:12 DEBUG[2931]: Manager received command '' Apr 12 19:01:12 DEBUG[2931]: Manager received command 'Logoff' Apr 12 19:01:12 VERBOSE[2931]: == Manager 'admin' logged off from 127.0.0.1 Apr 12 19:01:12 DEBUG[2931]: Unable to find key '1001' in family 'CW' Apr 12 19:01:12 VERBOSE[2931]: dialparties.agi: Extension 1001 has call waiting disabled Apr 12 19:01:12 VERBOSE[2931]: -- dialparties.agi: DbSet CALLTRACE/1001 to 90594803 Apr 12 19:01:12 VERBOSE[2931]: dialparties.agi: Dial string is ZAP/1|20|tr Apr 12 19:01:12 VERBOSE[2931]: -- AGI Script dialparties.agi completed, returning 0 Apr 12 19:01:12 VERBOSE[2931]: -- Executing Dial("Zap/3-1", "ZAP/1|20|tr") in new stack Apr 12 19:01:12 DEBUG[2931]: SIMPLE DIAL (NO URL) Apr 12 19:01:12 VERBOSE[2931]: -- Called 1 Apr 12 19:01:12 VERBOSE[2931]: -- Zap/1-1 is ringing Apr 12 19:01:14 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:14 DEBUG[2931]: Got event Ring/Answered(2) on channel 1 (index 0) Apr 12 19:01:14 DEBUG[2931]: Enabled echo cancellation on channel 1 Apr 12 19:01:14 DEBUG[2931]: Engaged echo training on channel 1 Apr 12 19:01:14 DEBUG[2931]: channel 1 answered Apr 12 19:01:14 DEBUG[2931]: Dropping duplicate answer! Apr 12 19:01:14 VERBOSE[2931]: -- Zap/1-1 answered Zap/3-1 Apr 12 19:01:16 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:16 DEBUG[2931]: Got event On hook(1) on channel 1 (index 0) Apr 12 19:01:16 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:01:16 DEBUG[2931]: Didn't get a frame from channel: Zap/1-1 Apr 12 19:01:16 DEBUG[2931]: Bridge stops bridging channels Zap/3-1 and Zap/1-1 Apr 12 19:01:16 DEBUG[2931]: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1 Apr 12 19:01:16 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:01:16 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/1-1 Apr 12 19:01:16 DEBUG[2931]: Updated conferencing on 1, with 0 conference users Apr 12 19:01:16 VERBOSE[2931]: -- Hungup 'Zap/1-1' Apr 12 19:01:16 DEBUG[2931]: Exiting with DIALSTATUS=ANSWER. Apr 12 19:01:16 VERBOSE[2931]: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/3-1' in macro 'dial' Apr 12 19:01:16 VERBOSE[2931]: == Spawn extension (macro-exten-vm, s, 3) exited non-zero on 'Zap/3-1' in macro 'exten-vm' Apr 12 19:01:16 VERBOSE[2931]: == Spawn extension (ext-local, 1001, 1) exited non-zero on 'Zap/3-1' Apr 12 19:01:16 DEBUG[2931]: cdr_mysql: inserting a CDR record. Apr 12 19:01:16 DEBUG[2931]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-04-12 19:01:02','\"90594803\" <90594803>','90594803','1001','ext-local', 'Zap/3-1','Zap/1-1','Monitor','wav49|20060412-190112-1144882859.26| mX',14,14,'ANSWERED',3,'') Apr 12 19:01:16 DEBUG[2931]: Hangup: channel: 3 index = 0, normal = 18, callwait = -1, thirdcall = -1 Apr 12 19:01:16 DEBUG[2931]: disabled echo cancellation on channel 3 Apr 12 19:01:16 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/3-1 Apr 12 19:01:16 DEBUG[2931]: Updated conferencing on 3, with 0 conference users Apr 12 19:01:16 VERBOSE[2931]: -- Hungup 'Zap/3-1' Apr 12 19:01:16 VERBOSE[2931]: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/20060412-190112-1144882859.26-in.WAV" "/var/spool/asterisk/monitor/20060412-190112-1144882859.26-out.WAV" "/var/spool/asterisk/monitor/20060412-190112-1144882859.26.WAV" && rm -f "/var/spool/asterisk/monitor/20060412-190112-1144882859.26-"* ) & Apr 12 19:01:20 DEBUG[2931]: Message status for 1001@default changed from -1 to 0 on 1 ######################################################################### ######################################################################### Make New Call Unable to Detect Called ID ######################################################################### ######################################################################### Apr 12 19:01:22 VERBOSE[2931]: -- Starting simple switch on 'Zap/3-1' Apr 12 19:01:23 ERROR[2931]: fsk_serie made mylen < 0 (-137) Apr 12 19:01:23 WARNING[2931]: CallerID feed failed: Success Apr 12 19:01:23 WARNING[2931]: CallerID returned with error on channel 'Zap/3-1' Apr 12 19:01:23 DEBUG[2931]: Expression is '1' Apr 12 19:01:23 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?from-pstn-reghours|s|1:") in new stack Apr 12 19:01:23 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,1) Apr 12 19:01:23 DEBUG[2931]: Expression is '0' Apr 12 19:01:23 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?from-pstn-reghours-nofax|s|1:2") in new stack Apr 12 19:01:23 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,2) Apr 12 19:01:23 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:01:23 DEBUG[2931]: Took Zap/3-1 off hook Apr 12 19:01:23 DEBUG[2931]: Enabled echo cancellation on channel 3 Apr 12 19:01:23 DEBUG[2931]: Engaged echo training on channel 3 Apr 12 19:01:23 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:01:24 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:01:24 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "intype=aa_1") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Executing Cut("Zap/3-1", "intype=intype|-|1") in new stack Apr 12 19:01:24 DEBUG[2931]: Expression is '0' Apr 12 19:01:24 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?7:9") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,9) Apr 12 19:01:24 DEBUG[2931]: Expression is '0' Apr 12 19:01:24 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?10:12") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,12) Apr 12 19:01:24 DEBUG[2931]: Expression is '0' Apr 12 19:01:24 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?13:15") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Goto (from-pstn-reghours,s,15) Apr 12 19:01:24 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "aa_1|s|1") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Goto (aa_1,s,1) Apr 12 19:01:24 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: = ANSWER ^^^^^^ ^ Apr 12 19:01:24 DEBUG[2931]: Expression is '0' Apr 12 19:01:24 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4") in new stack Apr 12 19:01:24 DEBUG[2931]: Not taking any branch Apr 12 19:01:24 VERBOSE[2931]: -- Executing Answer("Zap/3-1", "") in new stack Apr 12 19:01:24 VERBOSE[2931]: -- Executing Wait("Zap/3-1", "1") in new stack Apr 12 19:01:24 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:01:24 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:01:25 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "DIR-CONTEXT=general") in new stack Apr 12 19:01:25 VERBOSE[2931]: -- Executing DigitTimeout("Zap/3-1", "3") in new stack Apr 12 19:01:25 VERBOSE[2931]: -- Set Digit Timeout to 3 Apr 12 19:01:25 VERBOSE[2931]: -- Executing ResponseTimeout("Zap/3-1", "7") in new stack Apr 12 19:01:25 VERBOSE[2931]: -- Set Response Timeout to 7 Apr 12 19:01:25 VERBOSE[2931]: -- Executing BackGround("Zap/3-1", "custom/aa_1") in new stack Apr 12 19:01:25 WARNING[2931]: Not a wav file 49 Apr 12 19:01:25 WARNING[2931]: Unable to open fd on /var/lib/asterisk/sounds/custom/aa_1.wav Apr 12 19:01:25 WARNING[2931]: Unable to open custom/aa_1 (format unknown): No such file or directory Apr 12 19:01:25 WARNING[2931]: ast_streamfile failed on Zap/3-1 for custom/aa_1 Apr 12 19:01:25 DEBUG[2931]: DTMF digit: 1 on Zap/3-1 Apr 12 19:01:26 DEBUG[2931]: Manager received command 'Command' Apr 12 19:01:26 DEBUG[2931]: Manager received command 'Command' Apr 12 19:01:28 VERBOSE[2931]: == CDR updated on Zap/3-1 Apr 12 19:01:28 VERBOSE[2931]: -- Executing Goto("Zap/3-1", "ext-local|1001|1") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (ext-local,1001,1) Apr 12 19:01:28 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "exten-vm|novm|1001") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "FROMCONTEXT=exten-vm") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "record-enable|1001|IN") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0 > 0?2:4") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-record-enable,s,4) Apr 12 19:01:28 DEBUG[2931]: Expression is '0' Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?5:8") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-record-enable,s,8) Apr 12 19:01:28 DEBUG[2931]: Expression is '0' Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?9:12") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-record-enable,s,12) Apr 12 19:01:28 VERBOSE[2931]: -- Executing DBget("Zap/3-1", "RecEnable=RECORD-IN/1001") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- DBget: varname=RecEnable, family=RECORD-IN, key=1001 Apr 12 19:01:28 VERBOSE[2931]: -- DBget: set variable RecEnable to ENABLED Apr 12 19:01:28 VERBOSE[2931]: -- Executing SetVar("Zap/3-1", "CALLFILENAME=20060412-190128-1144882882.28") in new stack Apr 12 19:01:28 DEBUG[2931]: Expression is '1' Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "1?15:99") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-record-enable,s,15) Apr 12 19:01:28 VERBOSE[2931]: -- Executing Monitor("Zap/3-1", "wav49|20060412-190128-1144882882.28| mb") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Executing Macro("Zap/3-1", "dial|20|tr|1001") in new stack Apr 12 19:01:28 DEBUG[2931]: Expression is '0' Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:2") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-dial,s,2) Apr 12 19:01:28 WARNING[2931]: ast_yyerror(): syntax error: syntax error; Input: != ^ Apr 12 19:01:28 DEBUG[2931]: Expression is '0' Apr 12 19:01:28 VERBOSE[2931]: -- Executing GotoIf("Zap/3-1", "0?4:3") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Goto (macro-dial,s,3) Apr 12 19:01:28 VERBOSE[2931]: -- Executing SetCIDName("Zap/3-1", "") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Executing AGI("Zap/3-1", "dialparties.agi") in new stack Apr 12 19:01:28 VERBOSE[2931]: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: request = dialparties.agi Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: priority = 4 Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: extension = s Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: language = en Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: accountcode = Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: uniqueid = 1144882882.28 Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: channel = Zap/3-1 Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: callerid = unknown Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: context = macro-dial Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: type = Zap Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: rdnis = unknown Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: enhanced = 0.0 Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: dnid = unknown Apr 12 19:01:28 VERBOSE[2931]: dialparties.agi: Caller ID is not set Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: Added extension 1001 to extension map Apr 12 19:01:28 DEBUG[2931]: Unable to find key '1001' in family 'CF' Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: Extension 1001 cf is disabled Apr 12 19:01:28 DEBUG[2931]: Unable to find key '1001' in family 'DND' Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: Extension 1001 do not disturb is disabled Apr 12 19:01:28 DEBUG[2931]: Manager received command 'Login' Apr 12 19:01:28 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Apr 12 19:01:28 VERBOSE[2931]: == Parsing '/etc/asterisk/manager.conf': Found Apr 12 19:01:28 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Apr 12 19:01:28 VERBOSE[2931]: == Parsing '/etc/asterisk/manager_custom.conf': Found Apr 12 19:01:28 WARNING[2931]: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 19 of manager_custom.conf Apr 12 19:01:28 DEBUG[2931]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 12 19:01:28 DEBUG[2931]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:01:28 DEBUG[2931]: 192.108.130.166/255.255.255.0/255.255.255.0 appended to acl for peer Apr 12 19:01:28 DEBUG[2931]: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 12 19:01:28 DEBUG[2931]: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 12 19:01:28 DEBUG[2931]: ##### Testing 127.0.0.1 with 192.108.130.0 Apr 12 19:01:28 VERBOSE[2931]: == Manager 'admin' logged on from 127.0.0.1 Apr 12 19:01:28 DEBUG[2931]: Manager received command 'command' Apr 12 19:01:28 DEBUG[2931]: Manager received command '' Apr 12 19:01:28 DEBUG[2931]: Manager received command 'Logoff' Apr 12 19:01:28 VERBOSE[2931]: == Manager 'admin' logged off from 127.0.0.1 Apr 12 19:01:28 DEBUG[2931]: Unable to find key '1001' in family 'CW' Apr 12 19:01:28 VERBOSE[2931]: dialparties.agi: Extension 1001 has call waiting disabled Apr 12 19:01:28 VERBOSE[2931]: -- dialparties.agi: DbDel CALLTRACE/1001 - Caller ID is not defined Apr 12 19:01:28 VERBOSE[2931]: dialparties.agi: Dial string is ZAP/1|20|tr Apr 12 19:01:28 VERBOSE[2931]: -- AGI Script dialparties.agi completed, returning 0 Apr 12 19:01:28 VERBOSE[2931]: -- Executing Dial("Zap/3-1", "ZAP/1|20|tr") in new stack Apr 12 19:01:28 DEBUG[2931]: SIMPLE DIAL (NO URL) Apr 12 19:01:28 VERBOSE[2931]: -- Called 1 Apr 12 19:01:28 VERBOSE[2931]: -- Zap/1-1 is ringing Apr 12 19:01:29 DEBUG[2931]: Auto destroying call '24bdc86bfc3290f7@192.108.130.176' Apr 12 19:01:30 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:30 DEBUG[2931]: Got event Ringer Off(11) on channel 1 (index 0) Apr 12 19:01:30 VERBOSE[2931]: -- Zap/1-1 is ringing Apr 12 19:01:34 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:34 DEBUG[2931]: Got event Ringer On(10) on channel 1 (index 0) Apr 12 19:01:35 DEBUG[2931]: Auto destroying call 'f17f0bc1a5aac305@192.108.130.177' Apr 12 19:01:35 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:35 DEBUG[2931]: Got event Ring/Answered(2) on channel 1 (index 0) Apr 12 19:01:35 DEBUG[2931]: Enabled echo cancellation on channel 1 Apr 12 19:01:35 DEBUG[2931]: Engaged echo training on channel 1 Apr 12 19:01:35 DEBUG[2931]: channel 1 answered Apr 12 19:01:35 DEBUG[2931]: Dropping duplicate answer! Apr 12 19:01:35 VERBOSE[2931]: -- Zap/1-1 answered Zap/3-1 Apr 12 19:01:39 DEBUG[2931]: Exception on 15, channel 1 Apr 12 19:01:39 DEBUG[2931]: Got event On hook(1) on channel 1 (index 0) Apr 12 19:01:39 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:01:39 DEBUG[2931]: Didn't get a frame from channel: Zap/1-1 Apr 12 19:01:39 DEBUG[2931]: Bridge stops bridging channels Zap/3-1 and Zap/1-1 Apr 12 19:01:39 DEBUG[2931]: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1 Apr 12 19:01:39 DEBUG[2931]: disabled echo cancellation on channel 1 Apr 12 19:01:39 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/1-1 Apr 12 19:01:39 DEBUG[2931]: Updated conferencing on 1, with 0 conference users Apr 12 19:01:39 VERBOSE[2931]: -- Hungup 'Zap/1-1' Apr 12 19:01:39 DEBUG[2931]: Exiting with DIALSTATUS=ANSWER. Apr 12 19:01:39 VERBOSE[2931]: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/3-1' in macro 'dial' Apr 12 19:01:39 VERBOSE[2931]: == Spawn extension (macro-exten-vm, s, 3) exited non-zero on 'Zap/3-1' in macro 'exten-vm' Apr 12 19:01:39 VERBOSE[2931]: == Spawn extension (ext-local, 1001, 1) exited non-zero on 'Zap/3-1' Apr 12 19:01:39 DEBUG[2931]: cdr_mysql: inserting a CDR record. Apr 12 19:01:39 DEBUG[2931]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2006-04-12 19:01:23','','','1001','ext-local', 'Zap/3-1','Zap/1-1','Monitor','wav49|20060412-190128-1144882882.28| mX',16,16,'ANSWERED',3,'') Apr 12 19:01:39 DEBUG[2931]: Hangup: channel: 3 index = 0, normal = 18, callwait = -1, thirdcall = -1 Apr 12 19:01:39 DEBUG[2931]: disabled echo cancellation on channel 3 Apr 12 19:01:39 DEBUG[2931]: Set option TDD MODE, value: OFF(0) on Zap/3-1 Apr 12 19:01:39 DEBUG[2931]: Updated conferencing on 3, with 0 conference users Apr 12 19:01:39 VERBOSE[2931]: -- Hungup 'Zap/3-1' Apr 12 19:01:39 VERBOSE[2931]: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/20060412-190128-1144882882.28-in.WAV" "/var/spool/asterisk/monitor/20060412-190128-1144882882.28-out.WAV" "/var/spool/asterisk/monitor/20060412-190128-1144882882.28.WAV" && rm -f "/var/spool/asterisk/monitor/20060412-190128-1144882882.28-"* ) & Apr 12 19:01:43 DEBUG[2931]: Message status for 1001@default changed from -1 to 0 on 1 Apr 12 19:02:14 DEBUG[2931]: Auto destroying call '24bdc86bfc3290f7@192.108.130.176'