from inside: [root@asterisk1 asterisk]# tail -f /var/log/asterisk/full Dec 12 13:36:47 DEBUG[24210] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Dec 12 13:36:47 DEBUG[24210] chan_zap.c: disabled echo cancellation on channel 70 Dec 12 13:36:47 DEBUG[24210] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/70-1 Dec 12 13:36:47 DEBUG[24210] chan_zap.c: Updated conferencing on 70, with 0 conference users Dec 12 13:36:47 DEBUG[24210] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/70-1 Dec 12 13:36:47 DEBUG[24210] chan_zap.c: disabled echo cancellation on channel 70 Dec 12 13:36:47 VERBOSE[24210] logger.c: -- Hungup 'Zap/70-1' Dec 12 13:36:54 DEBUG[5484] chan_sip.c: Stopping retransmission on '715cc9d25e19c7e47aa7faba5f586fc5@192.168.1.250' of Request 102: Match Found Dec 12 13:37:01 DEBUG[5484] chan_sip.c: Auto destroying call '5a2cb396e953418601e9919413d2dcfb@192.168.1.106' Dec 12 13:37:09 DEBUG[5484] chan_sip.c: Stopping retransmission on '41f7d9aa19d12fbd2d7d55eb29b63dbc@192.168.1.250' of Request 102: Match Found Dec 12 13:37:15 DEBUG[5484] chan_sip.c: Setting NAT on RTP to 0 Dec 12 13:37:15 DEBUG[5484] chan_sip.c: Stopping retransmission on 'dfff00a8eb95c94b27b9b38f653c4f79@192.168.1.106' of Response 1653404035: Match Found Dec 12 13:37:15 DEBUG[5484] chan_sip.c: Setting NAT on RTP to 0 Dec 12 13:37:15 DEBUG[5484] chan_sip.c: Checking SIP call limits for device 6508 Dec 12 13:37:15 DEBUG[5484] chan_sip.c: build_route: Contact hop: sip:6508@192.168.1.106 Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Macro("SIP/6508-09930690", "exten-vm|6643|6643") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Macro("SIP/6508-09930690", "user-callerid") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0?report") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Not taking any branch Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0?start") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Not taking any branch Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '6508' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "REALCALLERIDNUM=6508") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing NoOp("SIP/6508-09930690", "REALCALLERIDNUM is 6508") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '6508' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "AMPUSER=6508") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is 'Scanner Station' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "AMPUSERCIDNAME=Scanner Station") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0?report") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Not taking any branch Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "CALLERID(all)=Scanner Station <6508>") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '6508' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "REALCALLERIDNUM=6508") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing NoOp("SIP/6508-09930690", "TTL: ARG1: 6643") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0?continue") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Not taking any branch Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '1' Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '-1' Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '64' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "_TTL=64") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '1' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "1?continue") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Goto (macro-user-callerid,s,20) Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '"Scanner Station" <6508>' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing NoOp("SIP/6508-09930690", "Using CallerID "Scanner Station" <6508>") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing NoOp("SIP/6508-09930690", "CAME FROM: ") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "RRNODEST=") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "_NODEST=") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "FROMCONTEXT=exten-vm") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "VMBOX=6643") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "EXTTOCALL=6643") in new stack Dec 12 13:37:15 DEBUG[24469] db.c: Unable to find key '6643' in family 'CFU' Dec 12 13:37:15 DEBUG[24469] func_db.c: DB: CFU/6643 not found in database. Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "CFUEXT=") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '1' Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:15 DEBUG[24469] pbx.c: Expression result is '1' Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '15' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Set("SIP/6508-09930690", "RT=15") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing Macro("SIP/6508-09930690", "record-enable|6643|IN") in new stack Dec 12 13:37:15 DEBUG[24469] pbx.c: Function result is '0' Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0 > 0?2:4") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Goto (macro-record-enable,s,4) Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Executing DeadAGI("SIP/6508-09930690", "recordingcheck|20061212-133715|1165952235.7712") in new stack Dec 12 13:37:15 VERBOSE[24469] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Dec 12 13:37:16 DEBUG[5484] chan_sip.c: Auto destroying call '8bccc3064f55ca2b1d4800cc42a8f7df@192.168.1.105' Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1114' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1113' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1106' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1101' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1111' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1115' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1105' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1103' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1109' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1112' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1102' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1108' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1107' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1110' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1104' to 60 seconds (requested 300) Dec 12 13:37:17 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1100' to 60 seconds (requested 300) Dec 12 13:37:17 VERBOSE[24469] logger.c: recordingcheck|20061212-133715|1165952235.7712: Inbound recording not enabled Dec 12 13:37:17 VERBOSE[24469] logger.c: -- AGI Script recordingcheck completed, returning 0 Dec 12 13:37:17 VERBOSE[24469] logger.c: -- Executing NoOp("SIP/6508-09930690", "No recording needed") in new stack Dec 12 13:37:17 DEBUG[24469] pbx.c: Expression result is '0' Dec 12 13:37:17 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "0?dolocaldial|1") in new stack Dec 12 13:37:17 DEBUG[24469] pbx.c: Not taking any branch Dec 12 13:37:17 VERBOSE[24469] logger.c: -- Executing Macro("SIP/6508-09930690", "dial|15|tr|6643") in new stack Dec 12 13:37:17 VERBOSE[24469] logger.c: -- Executing DeadAGI("SIP/6508-09930690", "dialparties.agi") in new stack Dec 12 13:37:17 VERBOSE[24469] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Dec 12 13:37:20 VERBOSE[24469] logger.c: dialparties.agi: Starting New Dialparties.agi Dec 12 13:37:20 VERBOSE[24469] logger.c: dialparties.agi: priority is 1 Dec 12 13:37:20 VERBOSE[24469] logger.c: dialparties.agi: Caller ID name is 'Scanner Station' number is '6508' Dec 12 13:37:20 VERBOSE[24469] logger.c: dialparties.agi: Methodology of ring is 'none' Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE' Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: RINGGROUP_INDEX: '' Dec 12 13:37:20 VERBOSE[24469] logger.c: -- dialparties.agi: Added extension 6643 to extension map Dec 12 13:37:20 DEBUG[24469] db.c: Unable to find key '6643' in family 'CF' Dec 12 13:37:20 VERBOSE[24469] logger.c: -- dialparties.agi: Extension 6643 cf is disabled Dec 12 13:37:20 DEBUG[24469] db.c: Unable to find key '6643' in family 'DND' Dec 12 13:37:20 VERBOSE[24469] logger.c: -- dialparties.agi: Extension 6643 do not disturb is disabled Dec 12 13:37:20 DEBUG[24469] db.c: Unable to find key '6643' in family 'CW' Dec 12 13:37:20 DEBUG[24469] db.c: Unable to find key '6643' in family 'CFB' Dec 12 13:37:20 DEBUG[24469] db.c: Unable to find key '6643' in family 'CFU' Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: extnum: 6643 Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: exthascw: 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: exthascfb: 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: extcfb: Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: exthascfu: 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: extcfu: Dec 12 13:37:20 DEBUG[24505] manager.c: Manager received command 'login' Dec 12 13:37:20 VERBOSE[24505] logger.c: == Parsing '/etc/asterisk/manager.conf': Dec 12 13:37:20 VERBOSE[24505] logger.c: == Parsing '/etc/asterisk/manager.conf': Found Dec 12 13:37:20 VERBOSE[24505] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Dec 12 13:37:20 VERBOSE[24505] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found Dec 12 13:37:20 DEBUG[24505] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Dec 12 13:37:20 DEBUG[24505] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Dec 12 13:37:20 DEBUG[24505] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Dec 12 13:37:20 DEBUG[24505] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 Dec 12 13:37:20 VERBOSE[24505] logger.c: == Manager 'admin' logged on from 127.0.0.1 Dec 12 13:37:20 DEBUG[24505] manager.c: Manager received command 'ExtensionState' Dec 12 13:37:20 DEBUG[24505] manager.c: Manager received command 'Logoff' Dec 12 13:37:20 VERBOSE[24505] logger.c: == Manager 'admin' logged off from 127.0.0.1 Dec 12 13:37:20 VERBOSE[24469] logger.c: > dialparties.agi: ExtensionState: 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: dialparties.agi: Extension 6643 has ExtensionState: 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 6643 Dec 12 13:37:20 VERBOSE[24469] logger.c: -- dialparties.agi: dbset CALLTRACE/6643 to 6508 Dec 12 13:37:20 VERBOSE[24469] logger.c: -- AGI Script dialparties.agi completed, returning 0 Dec 12 13:37:20 VERBOSE[24469] logger.c: -- Executing Dial("SIP/6508-09930690", "SIP/6643|15|tr") in new stack Dec 12 13:37:20 DEBUG[24469] chan_sip.c: Setting NAT on RTP to 0 Dec 12 13:37:20 DEBUG[24469] chan_sip.c: Outgoing Call for 6643 Dec 12 13:37:20 VERBOSE[24469] logger.c: -- Called 6643 Dec 12 13:37:20 DEBUG[5484] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5dabf33d3cbc751c56292d9246df1cc2@192.168.1.250' Request 102: Found Dec 12 13:37:20 DEBUG[5484] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5dabf33d3cbc751c56292d9246df1cc2@192.168.1.250' Request 102: Found Dec 12 13:37:20 VERBOSE[24469] logger.c: -- SIP/6643-098f50d0 is ringing Dec 12 13:37:21 DEBUG[24469] chan_sip.c: update_call_counter(6643) - decrement call limit counter Dec 12 13:37:21 DEBUG[24469] chan_sip.c: Acked pending invite 102 Dec 12 13:37:21 DEBUG[24469] chan_sip.c: Stopping retransmission on '5dabf33d3cbc751c56292d9246df1cc2@192.168.1.250' of Request 102: Match Found Dec 12 13:37:21 DEBUG[24469] app_dial.c: Exiting with DIALSTATUS=CANCEL. Dec 12 13:37:21 VERBOSE[24469] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'SIP/6508-09930690' in macro 'dial' Dec 12 13:37:21 VERBOSE[24469] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'SIP/6508-09930690' in macro 'exten-vm' Dec 12 13:37:21 VERBOSE[24469] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'SIP/6508-09930690' Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Executing Macro("SIP/6508-09930690", "hangupcall") in new stack Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Executing ResetCDR("SIP/6508-09930690", "w") in new stack Dec 12 13:37:21 DEBUG[24469] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Dec 12 13:37:21 DEBUG[24469] 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-12-12 13:37:15','\"Scanner Station\" <6508>','6508','6643','from-internal', 'SIP/6508-09930690','SIP/6643-098f50d0','ResetCDR','w',6,0,'NO ANSWER',3,'','1165952235.7712') Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Executing NoCDR("SIP/6508-09930690", "") in new stack Dec 12 13:37:21 WARNING[24469] cdr.c: CDR on channel 'SIP/6508-09930690' not posted Dec 12 13:37:21 WARNING[24469] cdr.c: CDR on channel 'SIP/6508-09930690' lacks end Dec 12 13:37:21 DEBUG[24469] pbx.c: Expression result is '1' Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Executing GotoIf("SIP/6508-09930690", "1?theend") in new stack Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Goto (macro-hangupcall,s,6) Dec 12 13:37:21 VERBOSE[24469] logger.c: -- Executing Wait("SIP/6508-09930690", "5") in new stack Dec 12 13:37:21 VERBOSE[24469] logger.c: == Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'SIP/6508-09930690' in macro 'hangupcall' Dec 12 13:37:21 VERBOSE[24469] logger.c: == Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'SIP/6508-09930690' Dec 12 13:37:21 DEBUG[24469] chan_sip.c: update_call_counter(6508) - decrement call limit counter Dec 12 13:37:21 DEBUG[5484] chan_sip.c: Stopping retransmission on '5dabf33d3cbc751c56292d9246df1cc2@192.168.1.250' of Request 102: Match Found Dec 12 13:37:21 DEBUG[5484] chan_sip.c: Stopping retransmission on '5dabf33d3cbc751c56292d9246df1cc2@192.168.1.250' of Request 102: Match Not Found Dec 12 13:37:21 DEBUG[5484] chan_sip.c: Stopping retransmission on 'dfff00a8eb95c94b27b9b38f653c4f79@192.168.1.106' of Response 1653404036: Match Found from outside: [root@asterisk1 asterisk]# tail -f /var/log/asterisk/full Dec 12 13:38:03 DEBUG[24517] chan_zap.c: waitfordigit returned < 0... Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/34-1 Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Hangup: channel: 34 index = 0, normal = 22, callwait = -1, thirdcall = -1 Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Dec 12 13:38:03 DEBUG[24517] chan_zap.c: disabled echo cancellation on channel 34 Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/34-1 Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Updated conferencing on 34, with 0 conference users Dec 12 13:38:03 DEBUG[24517] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/34-1 Dec 12 13:38:03 DEBUG[24517] chan_zap.c: disabled echo cancellation on channel 34 Dec 12 13:38:03 VERBOSE[24517] logger.c: -- Hungup 'Zap/34-1' Dec 12 13:38:09 DEBUG[5482] dsp.c: dsp busy pattern set to 2500,500 Dec 12 13:38:09 VERBOSE[5482] logger.c: -- Accepting overlap call from '3143926600' to '3926643' on channel 0/11, span 3 Dec 12 13:38:09 VERBOSE[24523] logger.c: -- Starting simple switch on 'Zap/59-1' Dec 12 13:38:12 DEBUG[24523] chan_zap.c: Enabled echo cancellation on channel 59 Dec 12 13:38:12 VERBOSE[24523] logger.c: -- Executing Dial("Zap/59-1", "Zap/g0/3926643") in new stack Dec 12 13:38:12 DEBUG[24523] dsp.c: dsp busy pattern set to 2500,500 Dec 12 13:38:12 VERBOSE[24523] logger.c: -- Requested transfer capability: 0x00 - SPEECH Dec 12 13:38:12 VERBOSE[24523] logger.c: -- Called g0/3926643 Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1114' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1113' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1106' to 60 seconds (requested 300) Dec 12 13:38:12 DEBUG[5481] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/8 span 2 Dec 12 13:38:12 VERBOSE[24523] logger.c: -- Zap/32-1 is proceeding passing it to Zap/59-1 Dec 12 13:38:12 DEBUG[24523] chan_zap.c: Requested indication 15 on channel Zap/59-1 Dec 12 13:38:12 DEBUG[24523] chan_zap.c: Received AST_CONTROL_PROCEEDING on Zap/59-1 Dec 12 13:38:12 DEBUG[5481] dsp.c: dsp busy pattern set to 2500,500 Dec 12 13:38:12 VERBOSE[5481] logger.c: -- Accepting overlap call from '3143926600' to '6643' on channel 0/10, span 2 Dec 12 13:38:12 VERBOSE[24534] logger.c: -- Starting simple switch on 'Zap/34-1' Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1101' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1111' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1115' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1105' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1103' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1109' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1112' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1102' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1108' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1107' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1110' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1104' to 60 seconds (requested 300) Dec 12 13:38:12 NOTICE[5475] chan_iax2.c: Restricting registration for peer '1100' to 60 seconds (requested 300) Dec 12 13:38:15 DEBUG[24534] chan_zap.c: Enabled echo cancellation on channel 34 Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Macro("Zap/34-1", "exten-vm|6643|6643") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Macro("Zap/34-1", "user-callerid") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '0' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "0?report") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Not taking any branch Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '0' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "0?start") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Not taking any branch Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '3143926600' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "REALCALLERIDNUM=3143926600") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing NoOp("Zap/34-1", "REALCALLERIDNUM is 3143926600") in new stack Dec 12 13:38:15 DEBUG[24534] db.c: Unable to find key '3143926600/user' in family 'DEVICE' Dec 12 13:38:15 DEBUG[24534] func_db.c: DB: DEVICE/3143926600/user not found in database. Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "AMPUSER=") in new stack Dec 12 13:38:15 DEBUG[24534] db.c: Unable to find key '/cidname' in family 'AMPUSER' Dec 12 13:38:15 DEBUG[24534] func_db.c: DB: AMPUSER//cidname not found in database. Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "AMPUSERCIDNAME=") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '1' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "1?report") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Goto (macro-user-callerid,s,10) Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing NoOp("Zap/34-1", "TTL: ARG1: 6643") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '0' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "0?continue") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Not taking any branch Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '1' Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '-1' Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '64' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "_TTL=64") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '1' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "1?continue") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Goto (macro-user-callerid,s,20) Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '"FRONTIER MORTGA" <3143926600>' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing NoOp("Zap/34-1", "Using CallerID "FRONTIER MORTGA" <3143926600>") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing NoOp("Zap/34-1", "CAME FROM: ") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "RRNODEST=") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "_NODEST=") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "FROMCONTEXT=exten-vm") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "VMBOX=6643") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "EXTTOCALL=6643") in new stack Dec 12 13:38:15 DEBUG[24534] db.c: Unable to find key '6643' in family 'CFU' Dec 12 13:38:15 DEBUG[24534] func_db.c: DB: CFU/6643 not found in database. Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "CFUEXT=") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '1' Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '0' Dec 12 13:38:15 DEBUG[24534] pbx.c: Expression result is '1' Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '15' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Set("Zap/34-1", "RT=15") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing Macro("Zap/34-1", "record-enable|6643|IN") in new stack Dec 12 13:38:15 DEBUG[24534] pbx.c: Function result is '0' Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "0 > 0?2:4") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Goto (macro-record-enable,s,4) Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Executing DeadAGI("Zap/34-1", "recordingcheck|20061212-133815|1165952292.7719") in new stack Dec 12 13:38:15 VERBOSE[24534] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Dec 12 13:38:18 VERBOSE[24534] logger.c: recordingcheck|20061212-133815|1165952292.7719: Inbound recording not enabled Dec 12 13:38:18 VERBOSE[24534] logger.c: -- AGI Script recordingcheck completed, returning 0 Dec 12 13:38:18 VERBOSE[24534] logger.c: -- Executing NoOp("Zap/34-1", "No recording needed") in new stack Dec 12 13:38:18 DEBUG[24534] pbx.c: Expression result is '0' Dec 12 13:38:18 VERBOSE[24534] logger.c: -- Executing GotoIf("Zap/34-1", "0?dolocaldial|1") in new stack Dec 12 13:38:18 DEBUG[24534] pbx.c: Not taking any branch Dec 12 13:38:18 VERBOSE[24534] logger.c: -- Executing Macro("Zap/34-1", "dial|15|tr|6643") in new stack Dec 12 13:38:18 VERBOSE[24534] logger.c: -- Executing DeadAGI("Zap/34-1", "dialparties.agi") in new stack Dec 12 13:38:18 VERBOSE[24534] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Dec 12 13:38:20 VERBOSE[5481] logger.c: -- Channel 0/10, span 2 got hangup request Dec 12 13:38:20 VERBOSE[5481] logger.c: -- PROGRESS with cause code 18 received Dec 12 13:38:20 DEBUG[5481] chan_zap.c: Queuing frame from PRI_EVENT_PROGRESS on channel 0/8 span 2 Dec 12 13:38:20 VERBOSE[24523] logger.c: -- Zap/32-1 is making progress passing it to Zap/59-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Requested indication 14 on channel Zap/59-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Received AST_CONTROL_PROGRESS on Zap/59-1 Dec 12 13:38:20 VERBOSE[24534] logger.c: dialparties.agi: Starting New Dialparties.agi Dec 12 13:38:20 VERBOSE[24534] logger.c: dialparties.agi: priority is 1 Dec 12 13:38:20 VERBOSE[24534] logger.c: dialparties.agi: Caller ID name is 'FRONTIER MORTGA' number is '3143926600' Dec 12 13:38:20 VERBOSE[24534] logger.c: dialparties.agi: Methodology of ring is 'none' Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE' Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: RINGGROUP_INDEX: '' Dec 12 13:38:20 VERBOSE[24534] logger.c: -- dialparties.agi: Added extension 6643 to extension map Dec 12 13:38:20 DEBUG[24534] db.c: Unable to find key '6643' in family 'CF' Dec 12 13:38:20 VERBOSE[24534] logger.c: -- dialparties.agi: Extension 6643 cf is disabled Dec 12 13:38:20 DEBUG[24534] db.c: Unable to find key '6643' in family 'DND' Dec 12 13:38:20 VERBOSE[24534] logger.c: -- dialparties.agi: Extension 6643 do not disturb is disabled Dec 12 13:38:20 DEBUG[24534] db.c: Unable to find key '6643' in family 'CW' Dec 12 13:38:20 DEBUG[24534] db.c: Unable to find key '6643' in family 'CFB' Dec 12 13:38:20 DEBUG[24534] db.c: Unable to find key '6643' in family 'CFU' Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: extnum: 6643 Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: exthascw: 0 Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: exthascfb: 0 Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: extcfb: Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: exthascfu: 0 Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: extcfu: Dec 12 13:38:20 DEBUG[24565] manager.c: Manager received command 'login' Dec 12 13:38:20 VERBOSE[24565] logger.c: == Parsing '/etc/asterisk/manager.conf': Dec 12 13:38:20 VERBOSE[24565] logger.c: == Parsing '/etc/asterisk/manager.conf': Found Dec 12 13:38:20 VERBOSE[24565] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Dec 12 13:38:20 VERBOSE[24565] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Found Dec 12 13:38:20 DEBUG[24565] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Dec 12 13:38:20 DEBUG[24565] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Dec 12 13:38:20 DEBUG[24565] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Dec 12 13:38:20 DEBUG[24565] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 Dec 12 13:38:20 VERBOSE[24565] logger.c: == Manager 'admin' logged on from 127.0.0.1 Dec 12 13:38:20 DEBUG[24565] manager.c: Manager received command 'ExtensionState' Dec 12 13:38:20 DEBUG[24565] manager.c: Manager received command 'Logoff' Dec 12 13:38:20 VERBOSE[24565] logger.c: == Manager 'admin' logged off from 127.0.0.1 Dec 12 13:38:20 VERBOSE[24534] logger.c: > dialparties.agi: ExtensionState: 0 Dec 12 13:38:20 VERBOSE[24534] logger.c: dialparties.agi: Extension 6643 has ExtensionState: 0 Dec 12 13:38:20 VERBOSE[24534] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 6643 Dec 12 13:38:20 VERBOSE[24534] logger.c: -- dialparties.agi: dbset CALLTRACE/6643 to 3143926600 Dec 12 13:38:20 VERBOSE[24534] logger.c: -- AGI Script dialparties.agi completed, returning 0 Dec 12 13:38:20 DEBUG[24534] app_macro.c: Extension s, macroexten 6643, priority 9 returned normally even though call was hung up Dec 12 13:38:20 DEBUG[24534] app_macro.c: Extension s, macroexten 6643, priority 12 returned normally even though call was hung up Dec 12 13:38:20 DEBUG[24534] pbx.c: Extension 6643, priority 1 returned normally even though call was hung up Dec 12 13:38:20 DEBUG[24534] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Dec 12 13:38:20 DEBUG[24534] 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-12-12 13:38:15','\"FRONTIER MORTGA\" <3143926600>','3143926600','6643','from-pstn', 'Zap/34-1','','DeadAGI','dialparties.agi',5,0,'NO ANSWER',2,'','1165952292.7719') Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/34-1 Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Hangup: channel: 34 index = 0, normal = 22, callwait = -1, thirdcall = -1 Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Dec 12 13:38:20 DEBUG[24534] chan_zap.c: disabled echo cancellation on channel 34 Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/34-1 Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Updated conferencing on 34, with 0 conference users Dec 12 13:38:20 DEBUG[24534] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/34-1 Dec 12 13:38:20 DEBUG[24534] chan_zap.c: disabled echo cancellation on channel 34 Dec 12 13:38:20 VERBOSE[24534] logger.c: -- Hungup 'Zap/34-1' Dec 12 13:38:20 VERBOSE[5482] logger.c: -- Channel 0/11, span 3 got hangup request Dec 12 13:38:20 DEBUG[24523] app_dial.c: Unable to forward frame Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/32-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Hangup: channel: 32 index = 0, normal = 20, callwait = -1, thirdcall = -1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Dec 12 13:38:20 DEBUG[24523] chan_zap.c: disabled echo cancellation on channel 32 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/32-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Updated conferencing on 32, with 0 conference users Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/32-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: disabled echo cancellation on channel 32 Dec 12 13:38:20 VERBOSE[24523] logger.c: -- Hungup 'Zap/32-1' Dec 12 13:38:20 DEBUG[24523] app_dial.c: Exiting with DIALSTATUS=CANCEL. Dec 12 13:38:20 VERBOSE[24523] logger.c: == Spawn extension (custom-to-from-alcatel, 3926643, 1) exited non-zero on 'Zap/59-1' Dec 12 13:38:20 DEBUG[24523] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Dec 12 13:38:20 DEBUG[24523] 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-12-12 13:38:12','\"test test\" <3143926600>','3143926600','3926643','custom-to-from-alcatel', 'Zap/59-1','Zap/32-1','Dial','Zap/g0/3926643',8,0,'NO ANSWER',2,'','1165952289.7717') Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/59-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Hangup: channel: 59 index = 0, normal = 39, callwait = -1, thirdcall = -1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Dec 12 13:38:20 DEBUG[24523] chan_zap.c: disabled echo cancellation on channel 59 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/59-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Updated conferencing on 59, with 0 conference users Dec 12 13:38:20 DEBUG[24523] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/59-1 Dec 12 13:38:20 DEBUG[24523] chan_zap.c: disabled echo cancellation on channel 59 Dec 12 13:38:20 VERBOSE[24523] logger.c: -- Hungup 'Zap/59-1'