Jul 12 23:07:10 DEBUG[2887] manager.c: Manager received command 'Command'
Jul 12 23:07:12 DEBUG[2887] manager.c: Manager received command 'Command'
Jul 12 23:07:12 DEBUG[2887] manager.c: Manager received command 'Command'
Jul 12 23:07:14 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
Jul 12 23:07:14 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
Jul 12 23:07:15 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
Jul 12 23:07:17 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for 63046446-7497abeb@10.1.2.3 - NOTIFY (No RTP)
Jul 12 23:07:17 DEBUG[1928] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
Jul 12 23:07:17 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for 4cde008a-f6bf1c77@10.1.2.3 - NOTIFY (No RTP)
Jul 12 23:07:17 DEBUG[1928] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for 53e2931e-f769f764@10.1.2.3 - INVITE (With RTP)
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: * SIP extension value: 2 for call 53e2931e-f769f764@10.1.2.3
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Setting NAT on RTP to 0
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Stopping retransmission on '53e2931e-f769f764@10.1.2.3' of Response 101: Match Found
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Setting NAT on RTP to 0
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Checking SIP call limits for device 200
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: Updating call counter for incoming call
Jul 12 23:07:29 DEBUG[1928] chan_sip.c: build_route: Contact hop: <sip:200@10.1.2.3:5060>
Jul 12 23:07:29 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:29 DEBUG[1848] devicestate.c: Changing state for SIP/200 - state 5 (Unavailable)
Jul 12 23:07:29 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "dialout-trunk|1|**********||") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '1'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "1?3:2") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Goto (macro-dialout-trunk,s,3)
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "user-callerid") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?report") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?start") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '200'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "REALCALLERIDNUM=200") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "REALCALLERIDNUM is 200") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '200'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "AMPUSER=200") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is 'House Phone'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "AMPUSERCIDNAME=House Phone") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?report") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "CALLERID(all)=House Phone <200>") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '"House Phone" <200>'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "Using CallerID "House Phone" <200>") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '200'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "record-enable|200|OUT") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0 > 0?2:4") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Goto (macro-record-enable,s,4)
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'AGI'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing AGI("SIP/200-242f", "recordingcheck|20060712-230729|1152760049.7") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 12 23:07:29 DEBUG[2890] app_queue.c: Device 'SIP/200' changed to state '5' (Unavailable)
Jul 12 23:07:29 VERBOSE[2889] logger.c:   recordingcheck|20060712-230729|1152760049.7: Outbound recording not enabled
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- AGI Script recordingcheck completed, returning 0
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "No recording needed") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "outbound-callerid|1") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '1'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "1?start") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Goto (macro-outbound-callerid,s,3)
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "REALCALLERIDNUM is 200") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is ''
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "USEROUTCID=") in new stack
Jul 12 23:07:29 DEBUG[2889] db.c: Unable to find key '200/emergency_cid' in family 'DEVICE'
Jul 12 23:07:29 DEBUG[2889] func_db.c: DB: DEVICE/200/emergency_cid not found in database.
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is ''
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "EMERGENCYCID=") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "TRUNKOUTCID=19898421586") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '1'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "1?trunkcid") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Goto (macro-outbound-callerid,s,11)
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?usercid") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "CALLERID(all)=19898421586") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '1'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "1?report") in new stack
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Goto (macro-outbound-callerid,s,15)
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '"" <19898421586>'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "CallerID set to "" <19898421586>") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "GROUP()=OUT_1") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Function result is '1'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?108") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "DIAL_NUMBER=**********") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "DIAL_TRUNK=1") in new stack
Jul 12 23:07:29 DEBUG[2889] pbx.c: Launching 'AGI'
Jul 12 23:07:29 VERBOSE[2889] logger.c:     -- Executing AGI("SIP/200-242f", "fixlocalprefix") in new stack
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- AGI Script fixlocalprefix completed, returning 0
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "OUTNUM=9**********") in new stack
Jul 12 23:07:30 DEBUG[2889] pbx.c: Function result is 'ZAP/g0'
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Set'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Set("SIP/200-242f", "custom=ZAP/g0") in new stack
Jul 12 23:07:30 DEBUG[2889] pbx.c: Expression result is '0'
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'GotoIf'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing GotoIf("SIP/200-242f", "0?16") in new stack
Jul 12 23:07:30 DEBUG[2889] pbx.c: Not taking any branch
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Dial'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Dial("SIP/200-242f", "ZAP/g0/9**********|120|r") in new stack
Jul 12 23:07:30 NOTICE[2889] app_dial.c: Unable to create channel of type 'ZAP' (cause 0 - Unknown)
Jul 12 23:07:30 VERBOSE[2889] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
Jul 12 23:07:30 DEBUG[2889] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Goto'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Goto("SIP/200-242f", "s-CHANUNAVAIL|1") in new stack
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'NoOp'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing NoOp("SIP/200-242f", "Dial failed due to CHANUNAVAIL") in new stack
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "outisbusy|") in new stack
Jul 12 23:07:30 DEBUG[2889] pbx.c: Launching 'Playback'
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Executing Playback("SIP/200-242f", "all-circuits-busy-now") in new stack
Jul 12 23:07:30 DEBUG[2889] chan_sip.c: sip_answer(SIP/200-242f)
Jul 12 23:07:30 DEBUG[2889] channel.c: Set channel SIP/200-242f to write format gsm
Jul 12 23:07:30 DEBUG[2889] rtp.c: Ooh, format changed from unknown to ulaw
Jul 12 23:07:30 DEBUG[2889] channel.c: Scheduling timer at 160 sample intervals
Jul 12 23:07:30 VERBOSE[2889] logger.c:     -- Playing 'all-circuits-busy-now' (language 'en')
Jul 12 23:07:30 DEBUG[1928] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
Jul 12 23:07:30 DEBUG[1928] chan_sip.c: Stopping retransmission on '53e2931e-f769f764@10.1.2.3' of Response 102: Match Found
Jul 12 23:07:30 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:30 DEBUG[1848] devicestate.c: Changing state for SIP/200 - state 5 (Unavailable)
Jul 12 23:07:30 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:30 DEBUG[2893] app_queue.c: Device 'SIP/200' changed to state '5' (Unavailable)
Jul 12 23:07:32 DEBUG[2889] channel.c: Scheduling timer at 0 sample intervals
Jul 12 23:07:32 DEBUG[2889] channel.c: Scheduling timer at 0 sample intervals
Jul 12 23:07:32 DEBUG[2889] channel.c: Set channel SIP/200-242f to write format ulaw
Jul 12 23:07:32 DEBUG[2889] pbx.c: Launching 'Playback'
Jul 12 23:07:32 VERBOSE[2889] logger.c:     -- Executing Playback("SIP/200-242f", "pls-try-call-later") in new stack
Jul 12 23:07:32 DEBUG[2889] channel.c: Set channel SIP/200-242f to write format gsm
Jul 12 23:07:32 DEBUG[2889] channel.c: Scheduling timer at 160 sample intervals
Jul 12 23:07:32 VERBOSE[2889] logger.c:     -- Playing 'pls-try-call-later' (language 'en')
Jul 12 23:07:32 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for 63046446-7497abeb@10.1.2.3 - NOTIFY (No RTP)
Jul 12 23:07:32 DEBUG[1928] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
Jul 12 23:07:32 DEBUG[1928] chan_sip.c: Allocating new SIP dialog for 4cde008a-f6bf1c77@10.1.2.3 - NOTIFY (No RTP)
Jul 12 23:07:32 DEBUG[1928] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
Jul 12 23:07:34 DEBUG[2889] channel.c: Scheduling timer at 0 sample intervals
Jul 12 23:07:34 DEBUG[2889] channel.c: Scheduling timer at 0 sample intervals
Jul 12 23:07:34 DEBUG[2889] channel.c: Set channel SIP/200-242f to write format ulaw
Jul 12 23:07:34 DEBUG[2889] pbx.c: Launching 'Macro'
Jul 12 23:07:34 VERBOSE[2889] logger.c:     -- Executing Macro("SIP/200-242f", "hangupcall") in new stack
Jul 12 23:07:34 DEBUG[2889] pbx.c: Launching 'ResetCDR'
Jul 12 23:07:34 VERBOSE[2889] logger.c:     -- Executing ResetCDR("SIP/200-242f", "w") in new stack
Jul 12 23:07:34 DEBUG[2889] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 12 23:07:34 DEBUG[2889] 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 ('2006-07-12 23:07:29','19898421586','19898421586','9**********','from-internal', 'SIP/200-242f','','ResetCDR','w',5,4,'ANSWERED',3,'','1152760049.7')
Jul 12 23:07:34 DEBUG[2889] pbx.c: Launching 'NoCDR'
Jul 12 23:07:34 VERBOSE[2889] logger.c:     -- Executing NoCDR("SIP/200-242f", "") in new stack
Jul 12 23:07:34 WARNING[2889] cdr.c: CDR on channel 'SIP/200-242f' not posted
Jul 12 23:07:34 WARNING[2889] cdr.c: CDR on channel 'SIP/200-242f' lacks end
Jul 12 23:07:34 DEBUG[2889] pbx.c: Launching 'Wait'
Jul 12 23:07:34 VERBOSE[2889] logger.c:     -- Executing Wait("SIP/200-242f", "5") in new stack
Jul 12 23:07:37 DEBUG[1928] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
Jul 12 23:07:37 DEBUG[2889] app_macro.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/200-242f' in macro 'hangupcall'
Jul 12 23:07:37 DEBUG[2889] app_macro.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/200-242f' in macro 'outisbusy'
Jul 12 23:07:37 DEBUG[2889] pbx.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/200-242f'
Jul 12 23:07:37 DEBUG[2889] channel.c: Hanging up channel 'SIP/200-242f'
Jul 12 23:07:37 DEBUG[2889] chan_sip.c: Hangup call SIP/200-242f, SIP callid 53e2931e-f769f764@10.1.2.3)
Jul 12 23:07:37 DEBUG[2889] chan_sip.c: update_call_counter(200) - decrement call limit counter
Jul 12 23:07:37 DEBUG[2889] chan_sip.c: Updating call counter for incoming call
Jul 12 23:07:37 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:37 DEBUG[1848] devicestate.c: Changing state for SIP/200 - state 5 (Unavailable)
Jul 12 23:07:37 DEBUG[1848] chan_sip.c: Checking device state for peer 200
Jul 12 23:07:37 DEBUG[2894] app_queue.c: Device 'SIP/200' changed to state '5' (Unavailable)