Dec 7 10:47:55 DEBUG[3700] chan_sip.c: Setting NAT on RTP to 524288 Dec 7 10:47:55 DEBUG[3700] chan_sip.c: Checking SIP call limits for device 402 Dec 7 10:47:55 DEBUG[3700] chan_sip.c: build_route: Contact hop: Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "dialout-trunk|2|0641293051||") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "DIAL_TRUNK=2") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "DIAL_NUMBER=0641293051") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "ROUTE_PASSWD=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?noauth") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-dialout-trunk,s,6) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?disabletrunk|1") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "_NODEST=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "DIAL_TRUNK_OPTIONS=tr") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "GROUP()=OUT_2") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "user-callerid|SKIPTTL") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is 'device' Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "user-callerid: device 402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Noop Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "AMPUSER=402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?report") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?start") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "REALCALLERIDNUM=402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "REALCALLERIDNUM is 402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: NoOp Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "AMPUSER=402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is 'Rick Jansen' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "AMPUSERCIDNAME=Rick Jansen") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?report") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '1' Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "AMPUSERCID=402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "CALLERID(all)="Rick Jansen" <402>") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "REALCALLERIDNUM=402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "TTL: ARG1: SKIPTTL") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Noop Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?continue") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-user-callerid,s,23) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '"Rick Jansen" <402>' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "Using CallerID "Rick Jansen" <402>") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: NoOp Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Macro Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '402' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "record-enable|402|OUT") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '0' Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?2:4") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-record-enable,s,4) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '20071207-104755' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing AGI("SIP/402-09bb7f48", "recordingcheck|20071207-104755|asterisk-3246-1197020875.1") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Dec 7 10:47:55 DEBUG[3700] chan_sip.c: Stopping retransmission on '3fce1b6a0cd064f2690cee7e6992eabc@192.168.20.2' of Request 102: Match Found Dec 7 10:47:55 VERBOSE[3956] logger.c: recordingcheck|20071207-104755|asterisk-3246-1197020875.1: Outbound recording not enabled Dec 7 10:47:55 VERBOSE[3956] logger.c: -- AGI Script recordingcheck completed, returning 0 Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: AGI Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "No recording needed") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Noop Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Macro Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?skipoutcid") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "DIAL_TRUNK_OPTIONS=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "outbound-callerid|2") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?start") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-outbound-callerid,s,3) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "REALCALLERIDNUM is 402") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: NoOp Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?normcid") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-outbound-callerid,s,9) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "USEROUTCID=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] db.c: Unable to find key '402/emergency_cid' in family 'DEVICE' Dec 7 10:47:55 DEBUG[3956] func_db.c: DB: DEVICE/402/emergency_cid not found in database. Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "EMERGENCYCID=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "TRUNKOUTCID=") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?trunkcid") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-outbound-callerid,s,16) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?usercid") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-outbound-callerid,s,18) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?report") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-outbound-callerid,s,22) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is '"Rick Jansen" <402>' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "CallerID set to "Rick Jansen" <402>") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: NoOp Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Macro Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?nomax") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-dialout-trunk,s,17) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing AGI("SIP/402-09bb7f48", "fixlocalprefix") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix Dec 7 10:47:55 VERBOSE[3956] logger.c: -- AGI Script fixlocalprefix completed, returning 0 Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: AGI Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "OUTNUM=0641293051") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Function result is 'ZAP/g0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Set("SIP/402-09bb7f48", "custom=ZAP/g0") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Set Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?gocall") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-dialout-trunk,s,22) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "dialout-trunk-predial-hook") in new stack Dec 7 10:47:55 WARNING[3956] app_macro.c: Context 'macro-dialout-trunk-predial-hook' for macro 'dialout-trunk-predial-hook' lacks 's' extension, priority 1 Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Macro Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?bypass|1") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '0' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "0?customtrunk") in new stack Dec 7 10:47:55 DEBUG[3956] pbx.c: Not taking any branch Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Dial("SIP/402-09bb7f48", "ZAP/g0/0641293051|300|") in new stack Dec 7 10:47:55 NOTICE[3956] app_dial.c: Unable to create channel of type 'ZAP' (cause 34 - Circuit/channel congestion) Dec 7 10:47:55 VERBOSE[3956] logger.c: == Everyone is busy/congested at this time (1:0/1/0) Dec 7 10:47:55 DEBUG[3956] app_dial.c: Exiting with DIALSTATUS=CONGESTION. Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Dial Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Goto("SIP/402-09bb7f48", "s-CONGESTION|1") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,1) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Goto Dec 7 10:47:55 DEBUG[3956] pbx.c: Expression result is '1' Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing GotoIf("SIP/402-09bb7f48", "1?noreport") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,3) Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: GotoIf Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing NoOp("SIP/402-09bb7f48", "TRUNK Dial failed due to CONGESTION - failing through to other trunks") in new stack Dec 7 10:47:55 DEBUG[3956] app_macro.c: Executed application: Noop Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Macro("SIP/402-09bb7f48", "outisbusy|") in new stack Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Executing Playback("SIP/402-09bb7f48", "all-circuits-busy-now|noanswer") in new stack Dec 7 10:47:55 DEBUG[3956] channel.c: Scheduling timer at 160 sample intervals Dec 7 10:47:55 VERBOSE[3956] logger.c: -- Playing 'all-circuits-busy-now' (language 'en') Dec 7 10:47:56 DEBUG[3956] channel.c: Scheduling timer at 0 sample intervals Dec 7 10:47:56 VERBOSE[3956] logger.c: == Spawn extension (macro-outisbusy, s, 1) exited non-zero on 'SIP/402-09bb7f48' in macro 'outisbusy' Dec 7 10:47:56 VERBOSE[3956] logger.c: == Spawn extension (macro-outisbusy, s, 1) exited non-zero on 'SIP/402-09bb7f48' Dec 7 10:47:56 DEBUG[3956] chan_sip.c: update_call_counter(402) - decrement call limit counter Dec 7 10:47:56 DEBUG[3956] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Dec 7 10:47:56 DEBUG[3956] 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,uniqueid) VALUES ('2007-12-07 10:47:55','\"Rick Jansen\" <402>','402','0641293051','from-internal', 'SIP/402-09bb7f48','','Playback','all-circuits-busy-now|noanswer',1,0,'FAILED',3,'','asterisk-3246-1197020875.1') Dec 7 10:47:56 DEBUG[3700] chan_sip.c: Stopping retransmission on 'MGM4OTk3ZmE2NDk3YzQ0OWRhYzU2M2QzYmVhMWUxNzE.' of Response 1: Match Found