Nov 6 14:38:47 DEBUG[4179] chan_sip.c: Checking SIP call limits for device 207
Nov 6 14:38:47 DEBUG[4179] chan_sip.c: build_route: Contact hop: <sip:207@10.25.3.83>
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Macro("SIP/207-089e0058", "dialout-trunk|6|0421063214||") in new st
ack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "DIAL_TRUNK=6") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "DIAL_NUMBER=0421063214") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "ROUTE_PASSWD=") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '1'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "1?noauth") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-dialout-trunk,s,6)
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "GROUP()=OUT_6") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Macro("SIP/207-089e0058", "user-callerid") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0?report") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Not taking any branch
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0?start") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Not taking any branch
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '207'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "REALCALLERIDNUM=207") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "REALCALLERIDNUM is 207") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '207'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "AMPUSER=207") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is 'Peter Zhu'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "AMPUSERCIDNAME=Peter Zhu") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0?report") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Not taking any branch
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "CALLERID(all)=Peter Zhu <207>") in new sta
ck
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '"Peter Zhu" <207>'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "Using CallerID "Peter Zhu" <207>") in new
stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '207'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Macro("SIP/207-089e0058", "record-enable|207|OUT") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0 > 0?2:4") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-record-enable,s,4)
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing DeadAGI("SIP/207-089e0058", "recordingcheck|20061106-143847|1162784
327.17") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Nov 6 14:38:47 VERBOSE[4320] logger.c: recordingcheck|20061106-143847|1162784327.17: Outbound recording not enabled
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- AGI Script recordingcheck completed, returning 0
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "No recording needed") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Macro("SIP/207-089e0058", "outbound-callerid|6") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '1'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "1?start") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-outbound-callerid,s,3)
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "REALCALLERIDNUM is 207") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is ''
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "USEROUTCID=") in new stack
Nov 6 14:38:47 DEBUG[4320] db.c: Unable to find key '207/emergency_cid' in family 'DEVICE'
Nov 6 14:38:47 DEBUG[4320] func_db.c: DB: DEVICE/207/emergency_cid not found in database.
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is ''
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "EMERGENCYCID=") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "TRUNKOUTCID=0388040804") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '1'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "1?trunkcid") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-outbound-callerid,s,11)
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0?usercid") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Not taking any branch
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "CALLERID(all)=0388040804") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '1'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "1?report") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-outbound-callerid,s,15)
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is '"" <0388040804>'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "CallerID set to "" <0388040804>") in new
stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '1'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "1?nomax") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Goto (macro-dialout-trunk,s,12)
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing AGI("SIP/207-089e0058", "fixlocalprefix") in new stack
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "OUTNUM=0421063214") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Function result is 'SIP/voiceblue'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Set("SIP/207-089e0058", "custom=SIP/voiceblue") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Expression result is '0'
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing GotoIf("SIP/207-089e0058", "0?customtrunk") in new stack
Nov 6 14:38:47 DEBUG[4320] pbx.c: Not taking any branch
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Executing Dial("SIP/207-089e0058", "SIP/voiceblue/0421063214|120|r") in new stack
Nov 6 14:38:47 DEBUG[4320] chan_sip.c: Setting NAT on RTP to 524288
Nov 6 14:38:47 DEBUG[4320] acl.c: ##### Testing 10.25.3.231 with 10.25.3.0
Nov 6 14:38:47 DEBUG[4320] chan_sip.c: Outgoing Call for 0421063214
Nov 6 14:38:47 VERBOSE[4320] logger.c: -- Called voiceblue/0421063214
Nov 6 14:38:47 DEBUG[4179] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55ce516a59b84c294c425c55695ac8ac@10.25.3.132' Request 102: Found
Nov 6 14:38:48 DEBUG[4179] acl.c: ##### Testing 220.240.81.246 with 10.25.3.0
Nov 6 14:38:48 DEBUG[4179] chan_sip.c: Target address 220.240.81.246 is not local, substituting externip
Nov 6 14:38:49 VERBOSE[4175] logger.c: -- Channel 0/2, span 1 got hangup request
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Echo cancellation already on
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Echo cancellation already on
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Unlinking slave 2 from 32
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Removed 12 from conference 3848/1023
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Removed 41 from conference 3848/1023
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Updated conferencing on 32, with 0 conference users
Nov 6 14:38:49 DEBUG[4288] channel.c: Returning from native bridge, channels: Zap/32-1, Zap/2-1
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/2-1
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Hangup: channel: 2 index = 0, normal = 12, callwait = -1, thirdcall = -1
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: disabled echo cancellation on channel 2
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Updated conferencing on 2, with 0 conference users
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/2-1
Nov 6 14:38:49 DEBUG[4288] chan_zap.c: disabled echo cancellation on channel 2
Nov 6 14:38:49 VERBOSE[4288] logger.c: -- Hungup 'Zap/2-1'
Nov 6 14:38:49 DEBUG[4288] app_dial.c: Exiting with DIALSTATUS=ANSWER.
....
Nov 6 14:39:17 DEBUG[4179] chan_sip.c: Stopping retransmission on '55ce516a59b84c294c425c55695ac8ac@10.25.3.132' of Request
102: Match Found
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- SIP/voiceblue-089e2c48 is circuit-busy
Nov 6 14:39:17 DEBUG[4320] chan_sip.c: update_call_counter(0421063214) - decrement call limit counter
Nov 6 14:39:17 VERBOSE[4320] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
Nov 6 14:39:17 DEBUG[4320] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Executing Goto("SIP/207-089e0058", "s-CONGESTION|1") in new stack
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,1)
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Executing NoOp("SIP/207-089e0058", "Dial failed due to CONGESTION - failing t
hrough to other trunks") in new stack
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Executing Macro("SIP/207-089e0058", "outisbusy|") in new stack
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Executing Playback("SIP/207-089e0058", "all-circuits-busy-now") in new stack
Nov 6 14:39:17 DEBUG[4320] channel.c: Scheduling timer at 160 sample intervals
Nov 6 14:39:17 VERBOSE[4320] logger.c: -- Playing 'all-circuits-busy-now' (language 'en')
Nov 6 14:39:17 DEBUG[4179] chan_sip.c: Stopping retransmission on '3457c71f437777f4@10.25.3.83' of Response 47241: Match Found
Nov 6 14:39:21 VERBOSE[4320] logger.c: -- Executing NoCDR("SIP/207-089e0058", "") in new stack
Nov 6 14:39:21 WARNING[4320] cdr.c: CDR on channel 'SIP/207-089e0058' not posted
Nov 6 14:39:21 WARNING[4320] cdr.c: CDR on channel 'SIP/207-089e0058' lacks end
Nov 6 14:39:21 VERBOSE[4320] logger.c: -- Executing Wait("SIP/207-089e0058", "5") in new stack
Nov 6 14:39:24 VERBOSE[4320] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/207-089e0058'in macro 'hangupcall'
Nov 6 14:39:24 VERBOSE[4320] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/207-089e0058'in macro 'outisbusy'
Nov 6 14:39:24 VERBOSE[4320] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/207-089e0058'
Nov 6 14:39:24 DEBUG[4320] chan_sip.c: update_call_counter(207) - decrement call limit cou