/var/log/asterisk/full - last 2000 lines

Oct 19 17:12:28 VERBOSE[2506] logger.c: Asterisk Event Logger restarted
Oct 19 17:12:28 VERBOSE[2506] logger.c: Asterisk Queue Logger restarted
Oct 19 17:12:43 VERBOSE[2687] logger.c: -- Starting simple switch on 'Zap/1-1'
Oct 19 17:12:47 NOTICE[2687] chan_zap.c: Got event 18 (Ring Begin)...
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "FROM_DID=s") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "FAX_RX=disabled") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Goto("Zap/1-1", "timeconditions|1|1") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Goto (timeconditions,1,1)
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing GotoIfTime("Zap/1-1", "08:00-17:25|mon-fri|*|*?ivr-2|s|1") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Goto (ivr-2,s,1)
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "LOOPCOUNT=0") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "__DIR-CONTEXT=default") in new stack
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Answer("Zap/1-1", "") in new stack
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Took Zap/1-1 off hook
Oct 19 17:12:47 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:12:47 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:12:47 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Enabled echo cancellation on channel 1
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Engaged echo training on channel 1
Oct 19 17:12:47 VERBOSE[2687] logger.c: -- Executing Wait("Zap/1-1", "1") in new stack
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Exception on 15, channel 1
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Got event Ring/Answered(2) on channel 1 (index 0)
Oct 19 17:12:47 DEBUG[2687] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
Oct 19 17:12:47 WARNING[2687] chan_zap.c: Ring/Off-hook in strange state 6 on channel 1
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "TIMEOUT(digit)=3") in new stack
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Digit timeout set to 3
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "TIMEOUT(response)=10") in new stack
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Response timeout set to 10
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Executing BackGround("Zap/1-1", "custom/Greeting") in new stack
Oct 19 17:12:48 DEBUG[2687] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:12:48 VERBOSE[2687] logger.c: -- Playing 'custom/Greeting' (language 'en')
Oct 19 17:12:51 DEBUG[2687] chan_zap.c: DTMF digit: 0 on Zap/1-1
Oct 19 17:12:51 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:51 DEBUG[2687] pbx.c: Oooh, got something to jump out with ('0')!
Oct 19 17:12:51 VERBOSE[2687] logger.c: == CDR updated on Zap/1-1
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing Goto("Zap/1-1", "ext-queues|100|1") in new stack
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Goto (ext-queues,100,1)
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing Answer("Zap/1-1", "") in new stack
Oct 19 17:12:51 DEBUG[2687] pbx.c: Expression result is '0'
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing GotoIf("Zap/1-1", "0?USERCID:SETCID") in new stack
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Goto (ext-queues,100,4)
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "CALLERID(name)=OPQueue") in new stack
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing Set("Zap/1-1", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q100-20061019-171251-1161303163.9") in new stack
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Executing Playback("Zap/1-1", "custom/OPQueueInitial") in new stack
Oct 19 17:12:51 DEBUG[2687] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:12:51 VERBOSE[2687] logger.c: -- Playing 'custom/OPQueueInitial' (language 'en')
Oct 19 17:12:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:12:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:12:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:12:57 DEBUG[2687] channel.c: Scheduling timer at 30 sample intervals
Oct 19 17:12:57 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:57 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:57 VERBOSE[2687] logger.c: -- Executing Queue("Zap/1-1", "100|t||custom/OPQueueCall") in new stack
Oct 19 17:12:57 VERBOSE[2687] logger.c: -- Started music on hold, class 'default', on Zap/1-1
Oct 19 17:12:57 DEBUG[2687] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:12:57 VERBOSE[2687] logger.c: -- Called Local/314@from-internal/n
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "exten-vm|314|314") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "user-callerid") in new stack
Oct 19 17:12:57 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "1?report") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Goto (macro-user-callerid,s,9)
Oct 19 17:12:57 DEBUG[2692] pbx.c: Function result is '"OPQueue" <>'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing NoOp("Local/314@from-internal-c5a4,2", "Using CallerID "OPQueue" <>") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "FROMCONTEXT=exten-vm") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "VMBOX=314") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "EXTTOCALL=314") in new stack
Oct 19 17:12:57 DEBUG[2692] db.c: Unable to find key '314' in family 'CFU'
Oct 19 17:12:57 DEBUG[2692] func_db.c: DB: CFU/314 not found in database.
Oct 19 17:12:57 DEBUG[2692] pbx.c: Function result is ''
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "CFUEXT=") in new stack
Oct 19 17:12:57 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:12:57 DEBUG[2692] pbx.c: Expression result is '0'
Oct 19 17:12:57 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:12:57 DEBUG[2692] pbx.c: Function result is '15'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "RT=15") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "record-enable|314|IN") in new stack
Oct 19 17:12:57 DEBUG[2692] pbx.c: Function result is '0'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "0 > 0?2:4") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Goto (macro-record-enable,s,4)
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing AGI("Local/314@from-internal-c5a4,2", "recordingcheck|20061019-171257|1161303177.11") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Oct 19 17:12:57 DEBUG[2687] channel.c: Generator got voice, switching to phase locked mode
Oct 19 17:12:57 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:57 VERBOSE[2692] logger.c: recordingcheck|20061019-171257|1161303177.11: Inbound recording not enabled
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- AGI Script recordingcheck completed, returning 0
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing NoOp("Local/314@from-internal-c5a4,2", "No recording needed") in new stack
Oct 19 17:12:57 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "1?dolocaldial|1") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Goto (macro-exten-vm,dolocaldial,1)
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "dial||tr|314") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing AGI("Local/314@from-internal-c5a4,2", "dialparties.agi") in new stack
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Oct 19 17:12:57 VERBOSE[2692] logger.c: dialparties.agi: Starting New Dialparties.agi
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- dialparties.agi: priority is 1
Oct 19 17:12:57 VERBOSE[2692] logger.c: dialparties.agi: Caller ID name is 'OPQueue' number is 'unknown'
Oct 19 17:12:57 VERBOSE[2692] logger.c: dialparties.agi: Methodology of ring is 'none'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- dialparties.agi: Added extension 314 to extension map
Oct 19 17:12:57 DEBUG[2692] db.c: Unable to find key '314' in family 'CF'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- dialparties.agi: Extension 314 cf is disabled
Oct 19 17:12:57 DEBUG[2692] db.c: Unable to find key '314' in family 'DND'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- dialparties.agi: Extension 314 do not disturb is disabled
Oct 19 17:12:57 DEBUG[2692] db.c: Unable to find key '314' in family 'CFB'
Oct 19 17:12:57 DEBUG[2692] db.c: Unable to find key '314' in family 'CFU'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- dialparties.agi: DbSet CALLTRACE/314 to unknown
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- AGI Script dialparties.agi completed, returning 0
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Executing Dial("Local/314@from-internal-c5a4,2", "SIP/314||tr") in new stack
Oct 19 17:12:57 DEBUG[2692] chan_sip.c: Setting NAT on RTP to 0
Oct 19 17:12:57 DEBUG[2692] chan_sip.c: Outgoing Call for 314
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- Called 314
Oct 19 17:12:57 VERBOSE[2687] logger.c: -- Local/314@from-internal-c5a4,1 is ringing
Oct 19 17:12:57 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7fb4126e0831b54c14f75722163a3eb0@192.168.2.8' Request 102: Found
Oct 19 17:12:57 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7fb4126e0831b54c14f75722163a3eb0@192.168.2.8' Request 102: Found
Oct 19 17:12:57 DEBUG[2339] channel.c: Avoiding initial deadlock for 'SIP/314-0928f460'
Oct 19 17:12:57 VERBOSE[2692] logger.c: -- SIP/314-0928f460 is ringing
Oct 19 17:12:58 DEBUG[2346] chan_sip.c: Acked pending invite 102
Oct 19 17:12:58 DEBUG[2346] chan_sip.c: Stopping retransmission on '7fb4126e0831b54c14f75722163a3eb0@192.168.2.8' of Request 102: Match Found
Oct 19 17:12:58 DEBUG[2346] chan_sip.c: build_route: Contact hop: 
Oct 19 17:12:58 VERBOSE[2692] logger.c: -- SIP/314-0928f460 answered Local/314@from-internal-c5a4,2
Oct 19 17:12:58 DEBUG[2687] app_queue.c: Dunno what to do with control type -1
Oct 19 17:12:58 VERBOSE[2687] logger.c: -- Local/314@from-internal-c5a4,1 answered Zap/1-1
Oct 19 17:12:58 DEBUG[2687] chan_zap.c: Set option TONE VERIFY, mode: MUTECONF(1) on Zap/1-1
Oct 19 17:12:58 DEBUG[2687] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:12:58 VERBOSE[2687] logger.c: -- Playing 'custom/OPQueueCall' (language 'en')
Oct 19 17:12:59 DEBUG[2687] channel.c: Scheduling timer at 125 sample intervals
Oct 19 17:12:59 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:59 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:12:59 VERBOSE[2687] logger.c: -- Stopped music on hold on Zap/1-1
Oct 19 17:12:59 DEBUG[2687] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:01 DEBUG[2692] channel.c: Got DTMF on channel (SIP/314-0928f460)
Oct 19 17:13:01 DEBUG[2692] channel.c: Bridge stops bridging channels Local/314@from-internal-c5a4,2 and SIP/314-0928f460
Oct 19 17:13:01 DEBUG[2692] res_features.c: Feature interpret: chan=Local/314@from-internal-c5a4,2, peer=SIP/314-0928f460, sense=2, features=2
Oct 19 17:13:01 DEBUG[2687] chan_zap.c: Requested indication 16 on channel Zap/1-1
Oct 19 17:13:01 VERBOSE[2692] logger.c: -- Started music on hold, class 'default', on Local/314@from-internal-c5a4,2
Oct 19 17:13:01 DEBUG[2692] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:13:01 DEBUG[2692] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:13:01 VERBOSE[2692] logger.c: -- Playing 'pbx-transfer' (language 'en')
Oct 19 17:13:01 DEBUG[2658] channel.c: Generator got voice, switching to phase locked mode
Oct 19 17:13:01 DEBUG[2658] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:02 DEBUG[2692] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:02 DEBUG[2692] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:02 DEBUG[2692] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:13:02 DEBUG[2692] channel.c: Generator got voice, switching to phase locked mode
Oct 19 17:13:02 DEBUG[2692] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:02 DEBUG[2692] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Stopped music on hold on Local/314@from-internal-c5a4,2
Oct 19 17:13:03 DEBUG[2692] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:13:03 DEBUG[2692] chan_sip.c: update_call_counter(314) - decrement call limit counter
Oct 19 17:13:03 DEBUG[2692] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Oct 19 17:13:03 VERBOSE[2692] logger.c: == Channel 'Local/314@from-internal-c5a4,2' jumping out of macro 'dial'
Oct 19 17:13:03 VERBOSE[2692] logger.c: == Channel 'Local/314@from-internal-c5a4,2' jumping out of macro 'exten-vm'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "exten-vm|315|315") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "user-callerid") in new stack
Oct 19 17:13:03 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "1?report") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Goto (macro-user-callerid,s,9)
Oct 19 17:13:03 DEBUG[2692] pbx.c: Function result is '"OPQueue" <>'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing NoOp("Local/314@from-internal-c5a4,2", "Using CallerID "OPQueue" <>") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "FROMCONTEXT=exten-vm") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "VMBOX=315") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "EXTTOCALL=315") in new stack
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'CFU'
Oct 19 17:13:03 DEBUG[2692] func_db.c: DB: CFU/315 not found in database.
Oct 19 17:13:03 DEBUG[2692] pbx.c: Function result is ''
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "CFUEXT=") in new stack
Oct 19 17:13:03 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:13:03 DEBUG[2692] pbx.c: Expression result is '0'
Oct 19 17:13:03 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:13:03 DEBUG[2692] pbx.c: Function result is '15'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Set("Local/314@from-internal-c5a4,2", "RT=15") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "record-enable|315|IN") in new stack
Oct 19 17:13:03 DEBUG[2692] pbx.c: Function result is '16'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "16 > 0?2:4") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Goto (macro-record-enable,s,2)
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing ResetCDR("Local/314@from-internal-c5a4,2", "w") in new stack
Oct 19 17:13:03 DEBUG[2687] chan_zap.c: Requested indication 17 on channel Zap/1-1
Oct 19 17:13:03 DEBUG[2692] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Oct 19 17:13:03 DEBUG[2692] cdr_addon_mysql.c: 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-10-19 17:12:57','OPQueue','','315','from-internal', 'Local/314@from-internal-c5a4,2','SIP/314-0928f460','ResetCDR','w',6,5,'ANSWERED',3,'')
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing StopMonitor("Local/314@from-internal-c5a4,2", "") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing AGI("Local/314@from-internal-c5a4,2", "recordingcheck|20061019-171303|1161303177.11") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Oct 19 17:13:03 VERBOSE[2692] logger.c: recordingcheck|20061019-171303|1161303177.11: Inbound recording not enabled
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- AGI Script recordingcheck completed, returning 0
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing NoOp("Local/314@from-internal-c5a4,2", "No recording needed") in new stack
Oct 19 17:13:03 DEBUG[2692] pbx.c: Expression result is '1'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing GotoIf("Local/314@from-internal-c5a4,2", "1?dolocaldial|1") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Goto (macro-exten-vm,dolocaldial,1)
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "dial||tr|315") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing AGI("Local/314@from-internal-c5a4,2", "dialparties.agi") in new stack
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Oct 19 17:13:03 DEBUG[2346] chan_sip.c: Stopping retransmission on '7fb4126e0831b54c14f75722163a3eb0@192.168.2.8' of Request 103: Match Found
Oct 19 17:13:03 VERBOSE[2692] logger.c: dialparties.agi: Starting New Dialparties.agi
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: priority is 1
Oct 19 17:13:03 VERBOSE[2692] logger.c: dialparties.agi: Caller ID name is 'OPQueue' number is 'unknown'
Oct 19 17:13:03 VERBOSE[2692] logger.c: dialparties.agi: Methodology of ring is 'none'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: Added extension 315 to extension map
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'CF'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: Extension 315 cf is disabled
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'DND'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: Extension 315 do not disturb is disabled
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'CW'
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'CFB'
Oct 19 17:13:03 DEBUG[2692] db.c: Unable to find key '315' in family 'CFU'
Oct 19 17:13:03 DEBUG[2703] manager.c: Manager received command 'login'
Oct 19 17:13:03 VERBOSE[2703] logger.c: == Parsing '/etc/asterisk/manager.conf': Oct 19 17:13:03 VERBOSE[2703] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Oct 19 17:13:03 VERBOSE[2703] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Oct 19 17:13:03 VERBOSE[2703] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Oct 19 17:13:03 DEBUG[2703] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Oct 19 17:13:03 DEBUG[2703] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Oct 19 17:13:03 DEBUG[2703] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Oct 19 17:13:03 DEBUG[2703] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Oct 19 17:13:03 VERBOSE[2703] logger.c: == Manager 'admin' logged on from 127.0.0.1
Oct 19 17:13:03 DEBUG[2703] manager.c: Manager received command 'ExtensionState'
Oct 19 17:13:03 DEBUG[2703] manager.c: Manager received command 'Logoff'
Oct 19 17:13:03 VERBOSE[2703] logger.c: == Manager 'admin' logged off from 127.0.0.1
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 315
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- dialparties.agi: DbSet CALLTRACE/315 to unknown
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- AGI Script dialparties.agi completed, returning 0
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Executing Dial("Local/314@from-internal-c5a4,2", "SIP/315||tr") in new stack
Oct 19 17:13:03 DEBUG[2692] chan_sip.c: Setting NAT on RTP to 0
Oct 19 17:13:03 DEBUG[2692] chan_sip.c: Outgoing Call for 315
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- Called 315
Oct 19 17:13:03 DEBUG[2687] channel.c: Got a FRAME_CONTROL (3) frame on channel Local/314@from-internal-c5a4,1
Oct 19 17:13:03 DEBUG[2687] channel.c: Bridge stops bridging channels Zap/1-1 and Local/314@from-internal-c5a4,1
Oct 19 17:13:03 DEBUG[2687] chan_zap.c: Requested indication 3 on channel Zap/1-1
Oct 19 17:13:03 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '007890cf39e701305f877e1243dc6c21@192.168.2.8' Request 102: Found
Oct 19 17:13:03 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '007890cf39e701305f877e1243dc6c21@192.168.2.8' Request 102: Found
Oct 19 17:13:03 DEBUG[2339] channel.c: Avoiding initial deadlock for 'SIP/315-0928f460'
Oct 19 17:13:03 VERBOSE[2692] logger.c: -- SIP/315-0928f460 is ringing
Oct 19 17:13:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:13:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:13:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:13:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:13:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:13:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:03 DEBUG[2346] chan_sip.c: Acked pending invite 102
Oct 19 17:14:03 DEBUG[2346] chan_sip.c: Stopping retransmission on '007890cf39e701305f877e1243dc6c21@192.168.2.8' of Request 102: Match Found
Oct 19 17:14:03 VERBOSE[2346] logger.c: -- Got SIP response 603 "Decline" back from 192.168.2.94
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- SIP/315-0928f460 is busy
Oct 19 17:14:03 DEBUG[2692] chan_sip.c: update_call_counter(315) - decrement call limit counter
Oct 19 17:14:03 VERBOSE[2692] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Oct 19 17:14:03 DEBUG[2692] app_dial.c: Exiting with DIALSTATUS=BUSY.
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing NoOp("Local/314@from-internal-c5a4,2", "Returned to dolocaldial with DIALSTATUS BUSY") in new stack
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing Hangup("Local/314@from-internal-c5a4,2", "") in new stack
Oct 19 17:14:03 VERBOSE[2692] logger.c: == Spawn extension (from-internal, 315, 2) exited non-zero on 'Local/314@from-internal-c5a4,2'
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing Macro("Local/314@from-internal-c5a4,2", "hangupcall") in new stack
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing ResetCDR("Local/314@from-internal-c5a4,2", "w") in new stack
Oct 19 17:14:03 DEBUG[2687] channel.c: Got a FRAME_CONTROL (-1) frame on channel Local/314@from-internal-c5a4,1
Oct 19 17:14:03 DEBUG[2687] channel.c: Bridge stops bridging channels Zap/1-1 and Local/314@from-internal-c5a4,1
Oct 19 17:14:03 DEBUG[2687] chan_zap.c: Requested indication -1 on channel Zap/1-1
Oct 19 17:14:03 DEBUG[2692] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Oct 19 17:14:03 DEBUG[2692] cdr_addon_mysql.c: 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-10-19 17:13:03','OPQueue','','315','from-internal', 'Local/314@from-internal-c5a4,2','SIP/315-0928f460','ResetCDR','w',60,0,'BUSY',3,'')
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing NoCDR("Local/314@from-internal-c5a4,2", "") in new stack
Oct 19 17:14:03 WARNING[2692] cdr.c: CDR on channel 'Local/314@from-internal-c5a4,2' not posted
Oct 19 17:14:03 WARNING[2692] cdr.c: CDR on channel 'Local/314@from-internal-c5a4,2' lacks end
Oct 19 17:14:03 VERBOSE[2692] logger.c: -- Executing Wait("Local/314@from-internal-c5a4,2", "5") in new stack
Oct 19 17:14:09 VERBOSE[2692] logger.c: -- Executing Hangup("Local/314@from-internal-c5a4,2", "") in new stack
Oct 19 17:14:09 VERBOSE[2692] logger.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'Local/314@from-internal-c5a4,2' in macro 'hangupcall'
Oct 19 17:14:09 VERBOSE[2692] logger.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'Local/314@from-internal-c5a4,2'
Oct 19 17:14:09 DEBUG[2687] channel.c: Didn't get a frame from channel: Local/314@from-internal-c5a4,1
Oct 19 17:14:09 DEBUG[2687] channel.c: Bridge stops bridging channels Zap/1-1 and Local/314@from-internal-c5a4,1
Oct 19 17:14:09 VERBOSE[2687] logger.c: == Spawn extension (ext-queues, 100, 7) exited non-zero on 'Zap/1-1'
Oct 19 17:14:09 DEBUG[2687] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Oct 19 17:14:09 DEBUG[2687] cdr_addon_mysql.c: 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-10-19 17:12:47','OPQueue','','100','ext-queues', 'Zap/1-1','Local/314@from-internal-c5a4,1','Queue','100|t||custom/OPQueueCall',82,82,'ANSWERED',3,'')
Oct 19 17:14:09 DEBUG[2687] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Oct 19 17:14:09 DEBUG[2687] chan_zap.c: disabled echo cancellation on channel 1
Oct 19 17:14:09 DEBUG[2687] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Oct 19 17:14:09 DEBUG[2687] chan_zap.c: Updated conferencing on 1, with 0 conference users
Oct 19 17:14:09 VERBOSE[2687] logger.c: -- Hungup 'Zap/1-1'
Oct 19 17:14:22 VERBOSE[2728] logger.c: -- Starting simple switch on 'Zap/1-1'
Oct 19 17:14:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:24 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:26 NOTICE[2728] chan_zap.c: Got event 18 (Ring Begin)...
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "FROM_DID=s") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "FAX_RX=disabled") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Goto("Zap/1-1", "timeconditions|1|1") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Goto (timeconditions,1,1)
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing GotoIfTime("Zap/1-1", "08:00-17:25|mon-fri|*|*?ivr-2|s|1") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Goto (ivr-2,s,1)
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "LOOPCOUNT=0") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "__DIR-CONTEXT=default") in new stack
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Answer("Zap/1-1", "") in new stack
Oct 19 17:14:26 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:14:26 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:14:26 DEBUG[2339] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Oct 19 17:14:26 DEBUG[2728] chan_zap.c: Took Zap/1-1 off hook
Oct 19 17:14:26 DEBUG[2728] chan_zap.c: Enabled echo cancellation on channel 1
Oct 19 17:14:26 DEBUG[2728] chan_zap.c: Engaged echo training on channel 1
Oct 19 17:14:26 VERBOSE[2728] logger.c: -- Executing Wait("Zap/1-1", "1") in new stack
Oct 19 17:14:27 DEBUG[2728] chan_zap.c: Exception on 15, channel 1
Oct 19 17:14:27 DEBUG[2728] chan_zap.c: Got event Ring/Answered(2) on channel 1 (index 0)
Oct 19 17:14:27 DEBUG[2728] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
Oct 19 17:14:27 WARNING[2728] chan_zap.c: Ring/Off-hook in strange state 6 on channel 1
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "TIMEOUT(digit)=3") in new stack
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Digit timeout set to 3
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "TIMEOUT(response)=10") in new stack
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Response timeout set to 10
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Executing BackGround("Zap/1-1", "custom/Greeting") in new stack
Oct 19 17:14:28 DEBUG[2728] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:14:28 VERBOSE[2728] logger.c: -- Playing 'custom/Greeting' (language 'en')
Oct 19 17:14:28 DEBUG[2346] chan_sip.c: Stopping retransmission on '2a5c86bc2e3c67ca0c47dcda6e81cd6a@206.40.216.140' of Request 102: Match Found
Oct 19 17:14:30 DEBUG[2728] chan_zap.c: DTMF digit: 3 on Zap/1-1
Oct 19 17:14:30 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:14:30 DEBUG[2728] pbx.c: Oooh, got something to jump out with ('3')!
Oct 19 17:14:30 DEBUG[2728] chan_zap.c: DTMF digit: 1 on Zap/1-1
Oct 19 17:14:31 DEBUG[2728] chan_zap.c: DTMF digit: 5 on Zap/1-1
Oct 19 17:14:31 VERBOSE[2728] logger.c: == CDR updated on Zap/1-1
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "exten-vm|315|315") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "user-callerid") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?report") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?start") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "REALCALLERIDNUM=") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "REALCALLERIDNUM is ") in new stack
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '/user' in family 'DEVICE'
Oct 19 17:14:31 DEBUG[2728] func_db.c: DB: DEVICE//user not found in database.
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "AMPUSER=") in new stack
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Oct 19 17:14:31 DEBUG[2728] func_db.c: DB: AMPUSER//cidname not found in database.
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "AMPUSERCIDNAME=") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "1?report") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Goto (macro-user-callerid,s,9)
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is '"" <>'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "Using CallerID "" <>") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "FROMCONTEXT=exten-vm") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "VMBOX=315") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "EXTTOCALL=315") in new stack
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'CFU'
Oct 19 17:14:31 DEBUG[2728] func_db.c: DB: CFU/315 not found in database.
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "CFUEXT=") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is '15'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "RT=15") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "record-enable|315|IN") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Function result is '0'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0 > 0?2:4") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Goto (macro-record-enable,s,4)
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing AGI("Zap/1-1", "recordingcheck|20061019-171431|1161303262.14") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Oct 19 17:14:31 VERBOSE[2728] logger.c: recordingcheck|20061019-171431|1161303262.14: Inbound recording not enabled
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- AGI Script recordingcheck completed, returning 0
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "No recording needed") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?dolocaldial|1") in new stack
Oct 19 17:14:31 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "dial|15|tr|315") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing AGI("Zap/1-1", "dialparties.agi") in new stack
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Oct 19 17:14:31 VERBOSE[2728] logger.c: dialparties.agi: Starting New Dialparties.agi
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: priority is 1
Oct 19 17:14:31 VERBOSE[2728] logger.c: dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
Oct 19 17:14:31 VERBOSE[2728] logger.c: dialparties.agi: Methodology of ring is 'none'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: Added extension 315 to extension map
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'CF'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: Extension 315 cf is disabled
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'DND'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: Extension 315 do not disturb is disabled
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'CW'
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'CFB'
Oct 19 17:14:31 DEBUG[2728] db.c: Unable to find key '315' in family 'CFU'
Oct 19 17:14:31 DEBUG[2733] manager.c: Manager received command 'login'
Oct 19 17:14:31 VERBOSE[2733] logger.c: == Parsing '/etc/asterisk/manager.conf': Oct 19 17:14:31 VERBOSE[2733] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Oct 19 17:14:31 VERBOSE[2733] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Oct 19 17:14:31 VERBOSE[2733] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found
Oct 19 17:14:31 DEBUG[2733] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Oct 19 17:14:31 DEBUG[2733] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Oct 19 17:14:31 DEBUG[2733] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Oct 19 17:14:31 DEBUG[2733] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Oct 19 17:14:31 VERBOSE[2733] logger.c: == Manager 'admin' logged on from 127.0.0.1
Oct 19 17:14:31 DEBUG[2733] manager.c: Manager received command 'ExtensionState'
Oct 19 17:14:31 DEBUG[2733] manager.c: Manager received command 'Logoff'
Oct 19 17:14:31 VERBOSE[2733] logger.c: == Manager 'admin' logged off from 127.0.0.1
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 315
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- dialparties.agi: DbSet CALLTRACE/315 to unknown
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- AGI Script dialparties.agi completed, returning 0
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Executing Dial("Zap/1-1", "SIP/315|15|tr") in new stack
Oct 19 17:14:31 DEBUG[2728] chan_sip.c: Setting NAT on RTP to 0
Oct 19 17:14:31 DEBUG[2728] chan_sip.c: Outgoing Call for 315
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- Called 315
Oct 19 17:14:31 DEBUG[2728] chan_zap.c: Requested indication 3 on channel Zap/1-1
Oct 19 17:14:31 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2214478b49a1a80027d408ef7ea397f8@192.168.2.8' Request 102: Found
Oct 19 17:14:31 DEBUG[2346] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '2214478b49a1a80027d408ef7ea397f8@192.168.2.8' Request 102: Found
Oct 19 17:14:31 DEBUG[2339] channel.c: Avoiding initial deadlock for 'SIP/315-0928f460'
Oct 19 17:14:31 VERBOSE[2728] logger.c: -- SIP/315-0928f460 is ringing
Oct 19 17:14:41 DEBUG[2346] chan_sip.c: Auto destroying call '8fc77b1b-4384fc3d@192.168.117.7'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Nobody picked up in 15000 ms
Oct 19 17:14:46 DEBUG[2728] chan_zap.c: Requested indication -1 on channel Zap/1-1
Oct 19 17:14:46 DEBUG[2728] chan_sip.c: update_call_counter(315) - decrement call limit counter
Oct 19 17:14:46 DEBUG[2728] chan_sip.c: Acked pending invite 102
Oct 19 17:14:46 DEBUG[2728] chan_sip.c: Stopping retransmission on '2214478b49a1a80027d408ef7ea397f8@192.168.2.8' of Request 102: Match Found
Oct 19 17:14:46 DEBUG[2728] app_dial.c: Exiting with DIALSTATUS=NOANSWER.
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GosubIf("Zap/1-1", "0?docfu|1") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "Voicemail is 315") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?s-NOANSWER|1") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "Sending to Voicemail box 315") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "vm|315|NOANSWER") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "user-callerid") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?report") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?start") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Not taking any branch
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "REALCALLERIDNUM=") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "REALCALLERIDNUM is ") in new stack
Oct 19 17:14:46 DEBUG[2728] db.c: Unable to find key '/user' in family 'DEVICE'
Oct 19 17:14:46 DEBUG[2728] func_db.c: DB: DEVICE//user not found in database.
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "AMPUSER=") in new stack
Oct 19 17:14:46 DEBUG[2728] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Oct 19 17:14:46 DEBUG[2728] func_db.c: DB: AMPUSER//cidname not found in database.
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is ''
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "AMPUSERCIDNAME=") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "1?report") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Goto (macro-user-callerid,s,9)
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is '"" <>'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "Using CallerID "" <>") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '1'
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is 'g(2)'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "VMGAIN=g(2)") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Goto("Zap/1-1", "s-NOANSWER|1") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Goto (macro-vm,s-NOANSWER,1)
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Macro("Zap/1-1", "get-vmcontext|315") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Function result is 'default'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing Set("Zap/1-1", "VMCONTEXT=default") in new stack
Oct 19 17:14:46 DEBUG[2728] pbx.c: Expression result is '0'
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing GotoIf("Zap/1-1", "0?200:300") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Goto (macro-get-vmcontext,s,300)
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing NoOp("Zap/1-1", "") in new stack
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Executing VoiceMail("Zap/1-1", "315@default|ug(2)") in new stack
Oct 19 17:14:46 DEBUG[2728] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:14:46 VERBOSE[2728] logger.c: -- Playing '/var/spool/asterisk/voicemail/default/315/unavail' (language 'en')
Oct 19 17:14:46 DEBUG[2346] chan_sip.c: Stopping retransmission on '2214478b49a1a80027d408ef7ea397f8@192.168.2.8' of Request 102: Match Found
Oct 19 17:14:47 DEBUG[2346] chan_sip.c: Stopping retransmission on '2214478b49a1a80027d408ef7ea397f8@192.168.2.8' of Request 102: Match Not Found
Oct 19 17:14:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:54 DEBUG[2643] manager.c: Manager received command 'Command'
Oct 19 17:14:54 DEBUG[2728] channel.c: Scheduling timer at 138 sample intervals
Oct 19 17:14:54 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:14:54 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:14:54 DEBUG[2728] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:14:54 VERBOSE[2728] logger.c: -- Playing 'vm-intro' (language 'en')
Oct 19 17:15:00 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:15:00 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:15:00 DEBUG[2728] app.c: Locked path '/var/spool/asterisk/voicemail/default/315/INBOX'
Oct 19 17:15:00 DEBUG[2728] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/315/INBOX'
Oct 19 17:15:00 DEBUG[2728] channel.c: Scheduling timer at 160 sample intervals
Oct 19 17:15:00 VERBOSE[2728] logger.c: -- Playing 'beep' (language 'en')
Oct 19 17:15:00 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:15:00 DEBUG[2728] channel.c: Scheduling timer at 0 sample intervals
Oct 19 17:15:00 VERBOSE[2728] logger.c: -- Recording the message
Oct 19 17:15:00 DEBUG[2728] chan_zap.c: Setting actual rx gain on Zap/1-1 to 10.200000
Oct 19 17:15:00 DEBUG[2728] app.c: play_and_record: , /var/spool/asterisk/voicemail/default/315/tmp/9vNSNJ, 'wav49|wav'
Oct 19 17:15:00 DEBUG[2728] app.c: Recording Formats: sfmts=wav49
Oct 19 17:15:00 VERBOSE[2728] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/315/tmp/9vNSNJ format: wav49, 0x92fdab8
Oct 19 17:15:00 VERBOSE[2728] logger.c: -- x=1, open writing: /var/spool/asterisk/voicemail/default/315/tmp/9vNSNJ format: wav, 0x92969c8
Oct 19 17:15:00 DEBUG[2728] chan_zap.c: Requested indication 18 on channel Zap/1-1
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Exception on 15, channel 1
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Got event On hook(1) on channel 1 (index 0)
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: disabled echo cancellation on channel 1
Oct 19 17:15:07 VERBOSE[2728] logger.c: -- User hung up
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Setting actual rx gain on Zap/1-1 to 8.200000
Oct 19 17:15:07 DEBUG[2728] app.c: Locked path '/var/spool/asterisk/voicemail/default/315/INBOX'
Oct 19 17:15:07 DEBUG[2728] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/315/INBOX'
Oct 19 17:15:07 DEBUG[2728] app_voicemail.c: Attaching file '/var/spool/asterisk/voicemail/default/315/INBOX/msg0002', format 'WAV', uservm is '2048', global is 2048
Oct 19 17:15:07 DEBUG[2728] app_voicemail.c: Sent mail to dhalvey@wfi-inc.com with command '/usr/sbin/sendmail -t'
Oct 19 17:15:07 VERBOSE[2728] logger.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'Zap/1-1' in macro 'vm'
Oct 19 17:15:07 VERBOSE[2728] logger.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'Zap/1-1' in macro 'exten-vm'
Oct 19 17:15:07 VERBOSE[2728] logger.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'Zap/1-1'
Oct 19 17:15:07 DEBUG[2728] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Oct 19 17:15:07 DEBUG[2728] cdr_addon_mysql.c: 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-10-19 17:14:26','','','315','ivr-2', 'Zap/1-1','SIP/315-0928f460','VoiceMail','315@default|ug(2)',41,41,'ANSWERED',3,'')
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: disabled echo cancellation on channel 1
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Oct 19 17:15:07 DEBUG[2728] chan_zap.c: Updated conferencing on 1, with 0 conference users
Oct 19 17:15:07 VERBOSE[2728] logger.c: -- Hungup 'Zap/1-1'
Oct 19 17:15:13 DEBUG[2346] chan_sip.c: Stopping retransmission on '6b90d80f7017984b33d9d2d966d9e0a9@192.168.2.8' of Request 102: Match Found
Oct 19 17:15:13 DEBUG[2346] chan_sip.c: Stopping retransmission on '6b90d80f7017984b33d9d2d966d9e0a9@192.168.2.8' of Request 102: Match Found