Sep  4 06:27:39 DEBUG[13671] chan_sip.c: Setting NAT on RTP to 0
Sep  4 06:27:39 DEBUG[13671] chan_sip.c: Stopping retransmission on '72db9c26-62d7b29a@10.0.20.235' of Response 101: Match Found
Sep  4 06:27:39 DEBUG[13671] chan_sip.c: Setting NAT on RTP to 0
Sep  4 06:27:39 DEBUG[13671] chan_sip.c: Checking SIP call limits for device 6795
Sep  4 06:27:39 DEBUG[13671] chan_sip.c: build_route: Contact hop: s6795 <sip:6795@10.0.20.235:5060>
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Macro("SIP/6795-08236550", "dialout-trunk|1|7274||") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "DIAL_TRUNK=1") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "DIAL_NUMBER=7274") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "ROUTE_PASSWD=") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?noauth") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-dialout-trunk,s,6)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "GROUP()=OUT_1") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Macro("SIP/6795-08236550", "user-callerid") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '0'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "0?report") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Not taking any branch
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '0'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "0?start") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Not taking any branch
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '6795'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "REALCALLERIDNUM=6795") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing NoOp("SIP/6795-08236550", "REALCALLERIDNUM is 6795") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: NoOp
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '6795'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "AMPUSER=6795") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is 's6795'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "AMPUSERCIDNAME=s6795") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '0'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "0?report") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Not taking any branch
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "CALLERID(all)=s6795 <6795>") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '"s6795" <6795>'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing NoOp("SIP/6795-08236550", "Using CallerID "s6795" <6795>") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: NoOp
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Macro
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '6795'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Macro("SIP/6795-08236550", "record-enable|6795|OUT") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '0'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "0 > 0?2:4") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-record-enable,s,4)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing AGI("SIP/6795-08236550", "recordingcheck|20070904-062739|1188898059.0") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Sep  4 06:27:39 VERBOSE[13892] logger.c:   recordingcheck|20070904-062739|1188898059.0: Outbound recording not enabled
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- AGI Script recordingcheck completed, returning 0
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: AGI
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing NoOp("SIP/6795-08236550", "No recording needed") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Noop
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Macro
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Macro("SIP/6795-08236550", "outbound-callerid|1") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?start") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-outbound-callerid,s,3)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing NoOp("SIP/6795-08236550", "REALCALLERIDNUM is 6795") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: NoOp
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is ''
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "USEROUTCID=") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] db.c: Unable to find key '6795/emergency_cid' in family 'DEVICE'
Sep  4 06:27:39 DEBUG[13892] func_db.c: DB: DEVICE/6795/emergency_cid not found in database.
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is ''
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "EMERGENCYCID=") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "TRUNKOUTCID=") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?trunkcid") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-outbound-callerid,s,11)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?usercid") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-outbound-callerid,s,13)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?report") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-outbound-callerid,s,15)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is '"s6795" <6795>'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing NoOp("SIP/6795-08236550", "CallerID set to "s6795" <6795>") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: NoOp
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Macro
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '1'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "1?nomax") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Goto (macro-dialout-trunk,s,12)
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing AGI("SIP/6795-08236550", "fixlocalprefix") in new stack
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Sep  4 06:27:39 VERBOSE[13892] logger.c:   fixlocalprefix: Could not parse /etc/asterisk/localprefixes.conf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- AGI Script fixlocalprefix completed, returning 0
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: AGI
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "OUTNUM=7274") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Function result is 'DGV/g2'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Set("SIP/6795-08236550", "custom=DGV/g2") in new stack
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: Set
Sep  4 06:27:39 DEBUG[13892] pbx.c: Expression result is '0'
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing GotoIf("SIP/6795-08236550", "0?customtrunk") in new stack
Sep  4 06:27:39 DEBUG[13892] pbx.c: Not taking any branch
Sep  4 06:27:39 DEBUG[13892] app_macro.c: Executed application: GotoIf
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Executing Dial("SIP/6795-08236550", "DGV/g2/7274|120|r") in new stack
Sep  4 06:27:39 NOTICE[13892] chan_dgv.c: Asked to get a channel DGV/g2/7274 using format AST_FORMAT_ULAW:ffWaveULaw
Sep  4 06:27:39 NOTICE[13892] chan_dgv.c: Group g2
Sep  4 06:27:39 VERBOSE[13892] logger.c:     -- Called g2/7274
Sep  4 06:27:41 VERBOSE[13892] logger.c:     -- DGV/31 is ringing
Sep  4 06:27:43 VERBOSE[13892] logger.c:     -- DGV/31 answered SIP/6795-08236550
Sep  4 06:27:43 DEBUG[13671] chan_sip.c: Stopping retransmission on '72db9c26-62d7b29a@10.0.20.235' of Response 102: Match Found
Sep  4 06:28:14 DEBUG[13892] channel.c: Didn't get a frame from channel: DGV/31
Sep  4 06:28:14 DEBUG[13892] channel.c: Bridge stops bridging channels SIP/6795-08236550 and DGV/31
Sep  4 06:28:14 NOTICE[13892] chan_dgv.c: Calling dg_HangUp on port 31 
Sep  4 06:28:14 DEBUG[13892] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Sep  4 06:28:14 VERBOSE[13892] logger.c:   == Spawn extension (macro-dialout-trunk, s, 16) exited non-zero on 'SIP/6795-08236550' in macro 'dialout-trunk'
Sep  4 06:28:14 VERBOSE[13892] logger.c:   == Spawn extension (macro-dialout-trunk, s, 16) exited non-zero on 'SIP/6795-08236550'
Sep  4 06:28:14 DEBUG[13892] chan_sip.c: update_call_counter(6795) - decrement call limit counter
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '"s6795" <6795>'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '6795'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '7274'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'from-internal'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'SIP/6795-08236550'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'DGV/31'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'Dial'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'DGV/g2/7274|120|r'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '2007-09-04 06:27:39'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '2007-09-04 06:27:43'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '2007-09-04 06:28:14'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '35'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '31'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'ANSWERED'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is 'DOCUMENTATION'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '(null)'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '1188898059.0'
Sep  4 06:28:14 DEBUG[13892] pbx.c: Function result is '(null)'
Sep  4 06:28:14 DEBUG[13892] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Sep  4 06:28:14 DEBUG[13892] 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-09-04 06:27:39','\"s6795\" <6795>','6795','7274','from-internal', 'SIP/6795-08236550','DGV/31','Dial','DGV/g2/7274|120|r',35,31,'ANSWERED',3,'','1188898059.0')
Sep  4 06:28:14 DEBUG[13671] chan_sip.c: Stopping retransmission on '72db9c26-62d7b29a@10.0.20.235' of Request 102: Match Found
Sep  4 06:28:18 DEBUG[13866] manager.c: Manager received command 'Command'
Sep  4 06:28:18 DEBUG[13866] manager.c: Manager received command 'Command'