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