Apr 26 19:56:39 DEBUG[2651] chan_sip.c: Auto destroying call '07ea23e52f9e4ae21055bfbb7bb80440@68.58.152.193' Apr 26 19:56:39 DEBUG[2651] chan_sip.c: Auto destroying call '7ae299e8670d3ddb17faa9e451031f1e@68.58.152.193' Apr 26 19:56:42 DEBUG[2651] acl.c: ##### Testing 172.16.9.102 with 172.16.9.0 Apr 26 19:56:42 DEBUG[2651] chan_sip.c: Setting NAT on RTP to 0 Apr 26 19:56:42 DEBUG[2651] chan_sip.c: Stopping retransmission on '0007ebcd-c4000097-071cf4f5-704c81ea@172.16.9.102' of Response 101: Match Found Apr 26 19:56:42 DEBUG[2651] chan_sip.c: Setting NAT on RTP to 0 Apr 26 19:56:42 DEBUG[2651] chan_sip.c: Checking SIP call limits for device 1000 Apr 26 19:56:42 DEBUG[2651] chan_sip.c: build_route: Contact hop: Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "dialout-trunk|6|393613||") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '1' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "1?3:2") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Goto (macro-dialout-trunk,s,3) Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "user-callerid") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1000' Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1000' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "AMPUSER=1000") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1000' Apr 26 19:56:42 DEBUG[7421] db.c: Unable to find key '1000/emergency_cid' in family 'DEVICE' Apr 26 19:56:42 DEBUG[7421] func_db.c: DB: DEVICE/1000/emergency_cid not found in database. Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "EMERGENCYCID=") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is 'Line 1' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "AMPUSERCIDNAME=Line 1") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '0' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "0?6") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Not taking any branch Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "CALLERID(all)="Line 1" <1000>") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '"Line 1" <1000>' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing NoOp("SIP/1000-16b5", "Using CallerID "Line 1" <1000>") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1000' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "record-enable|1000|OUT") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '0' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "0 > 0?2:4") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Goto (macro-record-enable,s,4) Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing AGI("SIP/1000-16b5", "recordingcheck|20060426-195642|1146095802.125") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Apr 26 19:56:42 VERBOSE[7421] logger.c: recordingcheck|20060426-195642|1146095802.125: Outbound recording not enabled Apr 26 19:56:42 VERBOSE[7421] logger.c: -- AGI Script recordingcheck completed, returning 0 Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing NoOp("SIP/1000-16b5", "No recording needed") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "outbound-callerid|6") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1000' Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "USEROUTCID=") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '0' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "0?4") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Not taking any branch Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "CALLERID(all)=767434") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '1' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "1?6") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Goto (macro-outbound-callerid,s,6) Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '1' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "1?8") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Goto (macro-outbound-callerid,s,8) Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '"" <767434>' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing NoOp("SIP/1000-16b5", "CallerID set to "" <767434>") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "GROUP()=OUT_6") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is '1' Apr 26 19:56:42 WARNING[7421] ast_expr2.fl: ast_yyerror(): syntax error: syntax error, unexpected $end, expecting TOK_MINUS or TOK_COMPL or TOK_LP or TOKEN; Input: 1 > ^ Apr 26 19:56:42 WARNING[7421] ast_expr2.fl: If you have questions, please refer to doc/README.variables in the asterisk source. Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '0' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "0?108") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Not taking any branch Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "DIAL_NUMBER=393613") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "DIAL_TRUNK=6") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing AGI("SIP/1000-16b5", "fixlocalprefix") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix Apr 26 19:56:42 VERBOSE[7421] logger.c: -- AGI Script fixlocalprefix completed, returning 0 Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "OUTNUM=393613") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Function result is 'SIP/fwd-sip' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Set("SIP/1000-16b5", "custom=SIP/fwd-sip") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Expression result is '0' Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing GotoIf("SIP/1000-16b5", "0?16") in new stack Apr 26 19:56:42 DEBUG[7421] pbx.c: Not taking any branch Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Dial("SIP/1000-16b5", "SIP/fwd-sip/393613|120|W") in new stack Apr 26 19:56:42 WARNING[7421] chan_sip.c: No such host: fwd-sip Apr 26 19:56:42 NOTICE[7421] app_dial.c: Unable to create channel of type 'SIP' (cause 3 - No route to destination) Apr 26 19:56:42 VERBOSE[7421] logger.c: == Everyone is busy/congested at this time (1:0/0/1) Apr 26 19:56:42 DEBUG[7421] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Goto("SIP/1000-16b5", "s-CHANUNAVAIL|1") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1) Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing NoOp("SIP/1000-16b5", "Dial failed due to CHANUNAVAIL") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "outisbusy|") in new stack Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Executing Playback("SIP/1000-16b5", "all-circuits-busy-now") in new stack Apr 26 19:56:42 DEBUG[2639] channel.c: Avoiding initial deadlock for 'SIP/1000-16b5' Apr 26 19:56:42 DEBUG[7421] channel.c: Scheduling timer at 160 sample intervals Apr 26 19:56:42 VERBOSE[7421] logger.c: -- Playing 'all-circuits-busy-now' (language 'en') Apr 26 19:56:42 DEBUG[2651] chan_sip.c: Stopping retransmission on '0007ebcd-c4000097-071cf4f5-704c81ea@172.16.9.102' of Response 102: Match Found Apr 26 19:56:44 DEBUG[7421] channel.c: Scheduling timer at 0 sample intervals Apr 26 19:56:44 DEBUG[7421] channel.c: Scheduling timer at 0 sample intervals Apr 26 19:56:44 VERBOSE[7421] logger.c: -- Executing Playback("SIP/1000-16b5", "pls-try-call-later") in new stack Apr 26 19:56:44 DEBUG[7421] channel.c: Scheduling timer at 160 sample intervals Apr 26 19:56:44 VERBOSE[7421] logger.c: -- Playing 'pls-try-call-later' (language 'en') Apr 26 19:56:46 DEBUG[7421] channel.c: Scheduling timer at 0 sample intervals Apr 26 19:56:46 DEBUG[7421] channel.c: Scheduling timer at 0 sample intervals Apr 26 19:56:46 VERBOSE[7421] logger.c: -- Executing Macro("SIP/1000-16b5", "hangupcall") in new stack Apr 26 19:56:46 VERBOSE[7421] logger.c: -- Executing ResetCDR("SIP/1000-16b5", "w") in new stack Apr 26 19:56:46 DEBUG[7421] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Apr 26 19:56:46 DEBUG[7421] 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-04-26 19:56:42','767434','767434','393613','from-internal', 'SIP/1000-16b5','','ResetCDR','w',4,4,'ANSWERED',3,'','1146095802.125') Apr 26 19:56:46 VERBOSE[7421] logger.c: -- Executing NoCDR("SIP/1000-16b5", "") in new stack Apr 26 19:56:46 WARNING[7421] cdr.c: CDR on channel 'SIP/1000-16b5' not posted Apr 26 19:56:46 WARNING[7421] cdr.c: CDR on channel 'SIP/1000-16b5' lacks end Apr 26 19:56:46 VERBOSE[7421] logger.c: -- Executing Wait("SIP/1000-16b5", "5") in new stack Apr 26 19:56:47 VERBOSE[7421] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/1000-16b5' in macro 'hangupcall' Apr 26 19:56:47 VERBOSE[7421] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/1000-16b5' in macro 'outisbusy' Apr 26 19:56:47 VERBOSE[7421] logger.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/1000-16b5' Apr 26 19:56:47 DEBUG[7421] chan_sip.c: update_call_counter(1000) - decrement call limit counter