May 8 11:50:17 DEBUG[3028] chan_sip.c: Setting NAT on RTP to 524288
May 8 11:50:17 DEBUG[3028] chan_sip.c: Stopping retransmission on '154258981-1988011443@10.10.53.200' of Response 1: Match Found
May 8 11:50:17 DEBUG[3028] chan_sip.c: Setting NAT on RTP to 524288
May 8 11:50:17 DEBUG[3028] chan_sip.c: Checking SIP call limits for device 1000
May 8 11:50:17 DEBUG[3028] chan_sip.c: build_route: Contact hop: <sip:1000@10.10.53.200:5060>
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Macro("SIP/1000-b36016a0", "dialout-trunk|1|2623233||") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "DIAL_TRUNK=1") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "_NODEST=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "DIAL_NUMBER=2623233") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "ROUTE_PASSWD=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "DIAL_TRUNK_OPTIONS=tr") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?noauth") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-dialout-trunk,s,8)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "GROUP()=OUT_1") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Macro("SIP/1000-b36016a0", "user-callerid|SKIPTTL") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is 'device'
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "user-callerid: device 1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Noop
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?report") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Not taking any branch
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?start") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Not taking any branch
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "REALCALLERIDNUM=1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "REALCALLERIDNUM is 1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: NoOp
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "AMPUSER=1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is 'Pruebas'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "AMPUSERCIDNAME=Pruebas") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?report") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Not taking any branch
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "CALLERID(all)=Pruebas <1000>") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "REALCALLERIDNUM=1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "TTL: ARG1: SKIPTTL") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Noop
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?continue") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-user-callerid,s,21)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '"Pruebas" <1000>'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "Using CallerID "Pruebas" <1000>") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: NoOp
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Macro
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Macro("SIP/1000-b36016a0", "record-enable|1000|OUT") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '0'
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?2:4") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-record-enable,s,4)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing DeadAGI("SIP/1000-b36016a0", "recordingcheck|20070508-115017|1178643017.9") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
May 8 11:50:17 VERBOSE[8741] logger.c: recordingcheck|20070508-115017|1178643017.9: Outbound recording not enabled
May 8 11:50:17 VERBOSE[8741] logger.c: -- AGI Script recordingcheck completed, returning 0
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: DeadAGI
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "No recording needed") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Noop
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Macro
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?skipoutcid") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Not taking any branch
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "DIAL_TRUNK_OPTIONS=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Macro("SIP/1000-b36016a0", "outbound-callerid|1") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?start") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-outbound-callerid,s,3)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "REALCALLERIDNUM is 1000") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: NoOp
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?normcid") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-outbound-callerid,s,9)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is ''
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "USEROUTCID=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] db.c: Unable to find key '1000/emergency_cid' in family 'DEVICE'
May 8 11:50:17 DEBUG[8741] func_db.c: DB: DEVICE/1000/emergency_cid not found in database.
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is ''
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "EMERGENCYCID=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "TRUNKOUTCID=") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?trunkcid") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-outbound-callerid,s,16)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?usercid") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-outbound-callerid,s,18)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?report") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-outbound-callerid,s,22)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is '"Pruebas" <1000>'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "CallerID set to "Pruebas" <1000>") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: NoOp
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Macro
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '1'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "1?nomax") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-dialout-trunk,s,16)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing DeadAGI("SIP/1000-b36016a0", "fixlocalprefix") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
May 8 11:50:17 VERBOSE[8741] logger.c: == fixlocalprefix: Dialpattern XXXXXXX matched. 2623233 -> 2623233
May 8 11:50:17 VERBOSE[8741] logger.c: -- AGI Script fixlocalprefix completed, returning 0
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: DeadAGI
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "OUTNUM=2623233") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Function result is 'ZAP/g0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Set("SIP/1000-b36016a0", "custom=ZAP/g0") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Set
May 8 11:50:17 DEBUG[8741] pbx.c: Expression result is '0'
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing GotoIf("SIP/1000-b36016a0", "0?customtrunk") in new stack
May 8 11:50:17 DEBUG[8741] pbx.c: Not taking any branch
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: GotoIf
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Dial("SIP/1000-b36016a0", "ZAP/g0/2623233|300|") in new stack
May 8 11:50:17 NOTICE[8741] app_dial.c: Unable to create channel of type 'ZAP' (cause 34 - Circuit/channel congestion)
May 8 11:50:17 VERBOSE[8741] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
May 8 11:50:17 DEBUG[8741] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Dial
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Goto("SIP/1000-b36016a0", "s-CONGESTION|1") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,1)
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: Goto
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing NoOp("SIP/1000-b36016a0", "Dial failed due to CONGESTION - failing through to other trunks") in new stack
May 8 11:50:17 DEBUG[8741] app_macro.c: Executed application: NoOp
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Macro("SIP/1000-b36016a0", "outisbusy|") in new stack
May 8 11:50:17 VERBOSE[8741] logger.c: -- Executing Playback("SIP/1000-b36016a0", "all-circuits-busy-now|noanswer") in new stack
May 8 11:50:17 DEBUG[8741] channel.c: Scheduling timer at 160 sample intervals
May 8 11:50:17 VERBOSE[8741] logger.c: -- Playing 'all-circuits-busy-now' (language 'en')
May 8 11:50:24 DEBUG[8741] channel.c: Scheduling timer at 0 sample intervals
May 8 11:50:24 VERBOSE[8741] logger.c: == Spawn extension (macro-outisbusy, s, 1) exited non-zero on 'SIP/1000-b36016a0' in macro 'outisbusy'
May 8 11:50:24 VERBOSE[8741] logger.c: == Spawn extension (macro-outisbusy, s, 1) exited non-zero on 'SIP/1000-b36016a0'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '"Pruebas" <1000>'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '1000'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '2623233'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'from-internal'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'SIP/1000-b36016a0'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '(null)'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'Playback'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'all-circuits-busy-now|noanswer'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '2007-05-08 11:50:17'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '(null)'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '2007-05-08 11:50:24'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '7'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '0'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'FAILED'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is 'DOCUMENTATION'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '(null)'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '1178643017.9'
May 8 11:50:24 DEBUG[8741] pbx.c: Function result is '(null)'
May 8 11:50:24 DEBUG[8741] chan_sip.c: update_call_counter(1000) - decrement call limit counter
May 8 11:50:24 DEBUG[3028] chan_sip.c: Stopping retransmission on '154258981-1988011443@10.10.53.200' of Response 2: Match Found
May 8 11:50:28 DEBUG[3028] chan_sip.c: Stopping retransmission on '7c3c26a64e65c3905a0fe1ef47e0b810@10.10.5.5' of Request 102: Match Found