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: <sip:402@217.149.222.66:5060>
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