Jul 25 16:38:12 DEBUG[5078] chan_sip.c: Allocating new SIP dialog for 712c3860-9a73fc7a-23b6395d@192.168.1.54 - SUBSCRIBE (No RTP)
Jul 25 16:38:14 DEBUG[5073] chan_zap.c: Monitor doohicky got event Ring Begin on channel 1
Jul 25 16:38:15 DEBUG[5073] chan_zap.c: Monitor doohicky got event Ring/Answered on channel 1
Jul 25 16:38:15 VERBOSE[6729] logger.c:     -- Starting simple switch on 'Zap/1-1'
Jul 25 16:38:15 DEBUG[6730] app_queue.c: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Jul 25 16:38:15 NOTICE[6729] chan_zap.c: Got event 18 (Ring Begin)...
Jul 25 16:38:15 NOTICE[6729] chan_zap.c: Got event 2 (Ring/Answered)...
Jul 25 16:38:17 NOTICE[6729] chan_zap.c: Got event 18 (Ring Begin)...
Jul 25 16:38:18 NOTICE[6729] chan_zap.c: Got event 2 (Ring/Answered)...
Jul 25 16:38:18 NOTICE[6729] chan_zap.c: Got event 18 (Ring Begin)...
Jul 25 16:38:18 NOTICE[6729] chan_zap.c: Got event 2 (Ring/Answered)...
Jul 25 16:38:20 NOTICE[6729] chan_zap.c: Got event 18 (Ring Begin)...
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'NoOp'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:1] NoOp("Zap/1-1", "Entering from-zaptel with DID == ") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Expression result is '1'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Function result is 's'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:2] Set("Zap/1-1", "DID=s") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'NoOp'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:3] NoOp("Zap/1-1", "DID is now s") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Expression result is '1'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'GotoIf'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:4] GotoIf("Zap/1-1", "1?zapok:notzap") in new stack
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Goto (from-zaptel,s,7)
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'NoOp'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:7] NoOp("Zap/1-1", "Is a Zaptel Channel") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:8] Set("Zap/1-1", "CHAN=1-1") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Function result is '1'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:9] Set("Zap/1-1", "CHAN=1") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Macro'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@from-zaptel:10] Macro("Zap/1-1", "from-zaptel-1|s|1") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'NoOp'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@macro-from-zaptel-1:1] NoOp("Zap/1-1", "Entering macro-from-zaptel-1 with DID = s") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@macro-from-zaptel-1:2] Set("Zap/1-1", "FROM_DID=s") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Goto'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [s@macro-from-zaptel-1:3] Goto("Zap/1-1", "ext-queues|5000|1") in new stack
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Goto (ext-queues,5000,1)
Jul 25 16:38:20 VERBOSE[6729] logger.c:   == Channel 'Zap/1-1' jumping out of macro 'from-zaptel-1'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Answer'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [5000@ext-queues:1] Answer("Zap/1-1", "") in new stack
Jul 25 16:38:20 DEBUG[6729] chan_zap.c: Took Zap/1-1 off hook
Jul 25 16:38:20 DEBUG[6729] chan_zap.c: Enabled echo cancellation on channel 1
Jul 25 16:38:20 WARNING[6729] chan_zap.c: Unable to request echo training on channel 1
Jul 25 16:38:20 DEBUG[6729] pbx.c: Expression result is '0'
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'GotoIf'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [5000@ext-queues:2] GotoIf("Zap/1-1", "0?USERCID:SETCID") in new stack
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Goto (ext-queues,5000,4)
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [5000@ext-queues:4] Set("Zap/1-1", "CALLERID(name)=") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [5000@ext-queues:5] Set("Zap/1-1", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q5000--1153809495.16") in new stack
Jul 25 16:38:20 DEBUG[6729] pbx.c: Launching 'Queue'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Executing [5000@ext-queues:6] Queue("Zap/1-1", "5000|t||") in new stack
Jul 25 16:38:20 DEBUG[6729] app_queue.c: queue: 5000, options: t, url: , announce: (null), expires: 0, priority: 0
Jul 25 16:38:20 DEBUG[6729] app_queue.c: Queue '5000' Join, Channel 'Zap/1-1', Position '1'
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Started music on hold, class 'default', on Zap/1-1
Jul 25 16:38:20 DEBUG[6729] channel.c: Scheduling timer at 160 sample intervals
Jul 25 16:38:20 DEBUG[6729] app_queue.c: It's our turn (Zap/1-1).
Jul 25 16:38:20 DEBUG[6729] app_queue.c: Zap/1-1 is trying to call a queue member.
Jul 25 16:38:20 DEBUG[6729] app_queue.c: (Parallel) Trying 'Local/5001@from-internal' with metric 0
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-6.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable MONITOR_FILENAME.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-5.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-4.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-2.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-1.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable MACRO_DEPTH.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-3.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable FROM_DID.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-2.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-1.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-10.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable CHAN.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-9.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-8.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-7.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-4.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-3.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable DID.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-2.
Jul 25 16:38:20 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-1.
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Macro'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [5001@from-internal:1] Macro("Local/5001@from-internal-f1fc,2", "exten-vm|novm|5001") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Macro'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("Local/5001@from-internal-f1fc,2", "user-callerid") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Expression result is '1'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'GotoIf'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-user-callerid:1] GotoIf("Local/5001@from-internal-f1fc,2", "1?report") in new stack
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Goto (macro-user-callerid,s,9)
Jul 25 16:38:20 DEBUG[6731] pbx.c: Function result is '"" <>'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'NoOp'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-user-callerid:9] NoOp("Local/5001@from-internal-f1fc,2", "Using CallerID "" <>") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:2] Set("Local/5001@from-internal-f1fc,2", "FROMCONTEXT=exten-vm") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:3] Set("Local/5001@from-internal-f1fc,2", "VMBOX=novm") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:4] Set("Local/5001@from-internal-f1fc,2", "EXTTOCALL=5001") in new stack
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CFU'
Jul 25 16:38:20 DEBUG[6731] func_db.c: DB: CFU/5001 not found in database.
Jul 25 16:38:20 DEBUG[6731] pbx.c: Function result is ''
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:5] Set("Local/5001@from-internal-f1fc,2", "CFUEXT=") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Expression result is '0'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Expression result is '0'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Expression result is '0'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Function result is ''
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Set'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:6] Set("Local/5001@from-internal-f1fc,2", "RT=") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Macro'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:7] Macro("Local/5001@from-internal-f1fc,2", "record-enable|5001|IN") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Function result is '0'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'GotoIf'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/5001@from-internal-f1fc,2", "0 > 0?2:4") in new stack
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Goto (macro-record-enable,s,4)
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'AGI'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-record-enable:4] AGI("Local/5001@from-internal-f1fc,2", "recordingcheck||1153809500.18") in new stack
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 25 16:38:20 DEBUG[6732] app_queue.c: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Jul 25 16:38:20 DEBUG[6733] app_queue.c: Device 'Local/5001@from-internal' changed to state '2' (In use)
Jul 25 16:38:20 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:20 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format slin
Jul 25 16:38:20 DEBUG[6729] res_musiconhold.c: Zap/1-1 Opened file 0 '/var/lib/asterisk/mohmp3/fpm-sunshine'
Jul 25 16:38:20 VERBOSE[6731] logger.c:   recordingcheck||1153809500.18: Inbound recording enabled.
Jul 25 16:38:20 VERBOSE[6731] logger.c:   recordingcheck||1153809500.18: CALLFILENAME=-1153809500.18
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- AGI Script recordingcheck completed, returning 0
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'MixMonitor'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-record-enable:999] MixMonitor("Local/5001@from-internal-f1fc,2", "-1153809500.18.wav|b") in new stack
Jul 25 16:38:20 DEBUG[6731] channel.c: Spy MixMonitor added to channel Local/5001@from-internal-f1fc,2
Jul 25 16:38:20 DEBUG[6731] pbx.c: Expression result is '1'
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'GotoIf'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-exten-vm:8] GotoIf("Local/5001@from-internal-f1fc,2", "1?dolocaldial|1") in new stack
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Goto (macro-exten-vm,dolocaldial,1)
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Macro'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [dolocaldial@macro-exten-vm:1] Macro("Local/5001@from-internal-f1fc,2", "dial|||5001") in new stack
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'AGI'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-dial:1] AGI("Local/5001@from-internal-f1fc,2", "dialparties.agi") in new stack
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jul 25 16:38:20 VERBOSE[6735] logger.c:   == Begin MixMonitor Recording Local/5001@from-internal-f1fc,2
Jul 25 16:38:20 VERBOSE[6731] logger.c:   dialparties.agi: Starting New Dialparties.agi
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: priority is 1
Jul 25 16:38:20 VERBOSE[6731] logger.c:   dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
Jul 25 16:38:20 VERBOSE[6731] logger.c:   dialparties.agi: Methodology of ring is  'none'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: Added extension 5001 to extension map
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CF'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: Extension 5001 cf is disabled
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'DND'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: Extension 5001 do not disturb is disabled
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CW'
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CFB'
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CFU'
Jul 25 16:38:20 DEBUG[6737] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jul 25 16:38:20 DEBUG[6737] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jul 25 16:38:20 DEBUG[6737] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Jul 25 16:38:20 DEBUG[6737] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: Checking CW and CFB status for extension 5001
Jul 25 16:38:20 DEBUG[6731] db.c: Unable to find key '5001' in family 'CALLTRACE'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     --  dialparties.agi: DbDel CALLTRACE/5001 - Caller ID is not defined
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- AGI Script dialparties.agi completed, returning 0
Jul 25 16:38:20 DEBUG[6731] pbx.c: Launching 'Dial'
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Executing [s@macro-dial:10] Dial("Local/5001@from-internal-f1fc,2", "SIP/5001||") in new stack
Jul 25 16:38:20 DEBUG[6731] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
Jul 25 16:38:20 DEBUG[6731] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Jul 25 16:38:20 DEBUG[6731] chan_sip.c: Setting NAT on RTP to Off
Jul 25 16:38:20 DEBUG[6731] rtp.c: Channel 'Local/5001@from-internal-f1fc,2' has no RTP, not doing anything
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-dial-s-10.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable MACRO_DEPTH.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable AGISTATUS.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable ds.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-dial-s-1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable ARG3.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable ARG2.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable ARG1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable MACRO_PRIORITY.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable MACRO_CONTEXT.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable MACRO_EXTEN.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-dolocaldial-1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-8.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable MIXMONITOR_FILENAME.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-record-enable-s-999.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable CALLFILENAME.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-record-enable-s-4.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-record-enable-s-1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-7.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable RT.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-6.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable CFUEXT.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-5.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable EXTTOCALL.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-4.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable VMBOX.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-3.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable FROMCONTEXT.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-2.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-user-callerid-s-9.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-user-callerid-s-1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-macro-exten-vm-s-1.
Jul 25 16:38:20 DEBUG[6731] channel.c: Not copying variable STACK-from-internal-5001-1.
Jul 25 16:38:20 DEBUG[6731] chan_sip.c: Outgoing Call for 5001
Jul 25 16:38:20 DEBUG[6731] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- Called 5001
Jul 25 16:38:20 DEBUG[6731] channel.c: Set channel SIP/5001-08683318 to read format ulaw
Jul 25 16:38:20 DEBUG[6731] channel.c: Set channel Local/5001@from-internal-f1fc,2 to write format ulaw
Jul 25 16:38:20 DEBUG[6731] channel.c: Set channel Local/5001@from-internal-f1fc,2 to read format ulaw
Jul 25 16:38:20 DEBUG[6731] channel.c: Set channel SIP/5001-08683318 to write format ulaw
Jul 25 16:38:20 DEBUG[5078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7d2c979f7afa09e002916a262897571f@192.168.1.16' Request 102: Found
Jul 25 16:38:20 DEBUG[5078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7d2c979f7afa09e002916a262897571f@192.168.1.16' Request 102: Found
Jul 25 16:38:20 VERBOSE[6731] logger.c:     -- SIP/5001-08683318 is ringing
Jul 25 16:38:20 DEBUG[6731] rtp.c: Channel 'Local/5001@from-internal-f1fc,2' has no RTP, not doing anything
Jul 25 16:38:20 VERBOSE[6729] logger.c:     -- Local/5001@from-internal-f1fc,1 is ringing
Jul 25 16:38:20 DEBUG[6738] app_queue.c: Device 'SIP/5001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul 25 16:38:36 VERBOSE[6729] logger.c:     -- Nobody picked up in 15000 ms
Jul 25 16:38:36 DEBUG[6729] app_queue.c: Zap/1-1: Nobody answered.
Jul 25 16:38:36 DEBUG[6729] channel.c: Hanging up channel 'Local/5001@from-internal-f1fc,1'
Jul 25 16:38:36 DEBUG[6731] rtp.c: Channel 'Local/5001@from-internal-f1fc,2' has no RTP, not doing anything
Jul 25 16:38:36 DEBUG[6731] channel.c: Hanging up channel 'SIP/5001-08683318'
Jul 25 16:38:36 DEBUG[6731] chan_sip.c: Hangup call SIP/5001-08683318, SIP callid 7d2c979f7afa09e002916a262897571f@192.168.1.16)
Jul 25 16:38:36 DEBUG[6731] chan_sip.c: Acked pending invite 102
Jul 25 16:38:36 DEBUG[6731] chan_sip.c: Stopping retransmission on '7d2c979f7afa09e002916a262897571f@192.168.1.16' of Request 102: Match Not Found
Jul 25 16:38:36 DEBUG[6731] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Jul 25 16:38:36 DEBUG[6731] app_macro.c: Spawn extension (macro-dial,s,10) exited non-zero on 'Local/5001@from-internal-f1fc,2' in macro 'dial'
Jul 25 16:38:36 DEBUG[6731] app_macro.c: Spawn extension (macro-dial,s,10) exited non-zero on 'Local/5001@from-internal-f1fc,2' in macro 'exten-vm'
Jul 25 16:38:36 DEBUG[6731] pbx.c: Spawn extension (macro-dial,s,10) exited non-zero on 'Local/5001@from-internal-f1fc,2'
Jul 25 16:38:36 DEBUG[5054] channel.c: Avoiding initial deadlock for channel '0x8630f00'
Jul 25 16:38:36 DEBUG[6731] channel.c: Spy MixMonitor removed from channel Local/5001@from-internal-f1fc,2
Jul 25 16:38:36 VERBOSE[6735] logger.c:   == End MixMonitor Recording Local/5001@from-internal-f1fc,2
Jul 25 16:38:36 DEBUG[6731] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 25 16:38:36 DEBUG[6731] 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) VALUES ('2006-07-25 16:38:20','','','5001','from-internal', 'Local/5001@from-internal-f1fc,2','SIP/5001-08683318','Dial','SIP/5001||',16,0,'NO ANSWER',3,'')
Jul 25 16:38:36 DEBUG[6731] channel.c: Hanging up channel 'Local/5001@from-internal-f1fc,2'
Jul 25 16:38:36 DEBUG[6739] app_queue.c: Device 'Local/5001@from-internal' changed to state '1' (Not in use)
Jul 25 16:38:36 DEBUG[6740] app_queue.c: Device 'SIP/5001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul 25 16:38:36 DEBUG[6741] app_queue.c: Device 'Local/5001@from-internal' changed to state '1' (Not in use)
Jul 25 16:38:36 DEBUG[5078] chan_sip.c: Stopping retransmission on '7d2c979f7afa09e002916a262897571f@192.168.1.16' of Request 102: Match Not Found
Jul 25 16:38:36 DEBUG[5078] chan_sip.c: Stopping retransmission on '7d2c979f7afa09e002916a262897571f@192.168.1.16' of Request 102: Match Found
Jul 25 16:38:41 DEBUG[6729] app_queue.c: It's our turn (Zap/1-1).
Jul 25 16:38:41 VERBOSE[6729] logger.c:     -- Stopped music on hold on Zap/1-1
Jul 25 16:38:41 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format ulaw
Jul 25 16:38:41 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:41 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format ulaw
Jul 25 16:38:41 DEBUG[6729] channel.c: Scheduling timer at 160 sample intervals
Jul 25 16:38:41 VERBOSE[6729] logger.c:     -- Playing 'queue-youarenext' (language 'en')
Jul 25 16:38:46 DEBUG[6729] channel.c: Scheduling timer at 146 sample intervals
Jul 25 16:38:46 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:46 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:46 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format ulaw
Jul 25 16:38:46 VERBOSE[6729] logger.c:     -- Told Zap/1-1 in 5000 their queue position (which was 1)
Jul 25 16:38:46 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format ulaw
Jul 25 16:38:46 DEBUG[6729] channel.c: Scheduling timer at 160 sample intervals
Jul 25 16:38:46 VERBOSE[6729] logger.c:     -- Playing 'queue-thankyou' (language 'en')
Jul 25 16:38:47 DEBUG[6729] channel.c: Scheduling timer at 86 sample intervals
Jul 25 16:38:47 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:47 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:47 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format ulaw
Jul 25 16:38:47 VERBOSE[6729] logger.c:     -- Started music on hold, class 'default', on Zap/1-1
Jul 25 16:38:47 DEBUG[6729] channel.c: Scheduling timer at 160 sample intervals
Jul 25 16:38:47 DEBUG[6729] app_queue.c: Zap/1-1 is trying to call a queue member.
Jul 25 16:38:47 DEBUG[6729] app_queue.c: (Parallel) Trying 'Local/5001@from-internal' with metric 0
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-6.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable MONITOR_FILENAME.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-5.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-4.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-2.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-ext-queues-5000-1.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable MACRO_DEPTH.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-3.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable FROM_DID.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-2.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-macro-from-zaptel-1-s-1.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-10.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable CHAN.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-9.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-8.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-7.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-4.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-3.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable DID.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-2.
Jul 25 16:38:47 DEBUG[6729] channel.c: Not copying variable STACK-from-zaptel-s-1.
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Macro'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [5001@from-internal:1] Macro("Local/5001@from-internal-cd25,2", "exten-vm|novm|5001") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Macro'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("Local/5001@from-internal-cd25,2", "user-callerid") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Expression result is '1'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'GotoIf'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-user-callerid:1] GotoIf("Local/5001@from-internal-cd25,2", "1?report") in new stack
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Goto (macro-user-callerid,s,9)
Jul 25 16:38:47 DEBUG[6742] pbx.c: Function result is '"" <>'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'NoOp'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-user-callerid:9] NoOp("Local/5001@from-internal-cd25,2", "Using CallerID "" <>") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Set'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:2] Set("Local/5001@from-internal-cd25,2", "FROMCONTEXT=exten-vm") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Set'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:3] Set("Local/5001@from-internal-cd25,2", "VMBOX=novm") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Set'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:4] Set("Local/5001@from-internal-cd25,2", "EXTTOCALL=5001") in new stack
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CFU'
Jul 25 16:38:47 DEBUG[6742] func_db.c: DB: CFU/5001 not found in database.
Jul 25 16:38:47 DEBUG[6742] pbx.c: Function result is ''
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Set'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:5] Set("Local/5001@from-internal-cd25,2", "CFUEXT=") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Expression result is '0'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Expression result is '0'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Expression result is '0'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Function result is ''
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Set'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:6] Set("Local/5001@from-internal-cd25,2", "RT=") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Macro'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:7] Macro("Local/5001@from-internal-cd25,2", "record-enable|5001|IN") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Function result is '0'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'GotoIf'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/5001@from-internal-cd25,2", "0 > 0?2:4") in new stack
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Goto (macro-record-enable,s,4)
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'AGI'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-record-enable:4] AGI("Local/5001@from-internal-cd25,2", "recordingcheck||1153809527.21") in new stack
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 25 16:38:47 DEBUG[6743] app_queue.c: Device 'Local/5001@from-internal' changed to state '2' (In use)
Jul 25 16:38:47 DEBUG[6729] channel.c: Scheduling timer at 0 sample intervals
Jul 25 16:38:47 DEBUG[6729] channel.c: Set channel Zap/1-1 to write format slin
Jul 25 16:38:47 DEBUG[6729] res_musiconhold.c: Zap/1-1 Opened file 0 '/var/lib/asterisk/mohmp3/fpm-sunshine'
Jul 25 16:38:47 VERBOSE[6742] logger.c:   recordingcheck||1153809527.21: Inbound recording enabled.
Jul 25 16:38:47 VERBOSE[6742] logger.c:   recordingcheck||1153809527.21: CALLFILENAME=-1153809527.21
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- AGI Script recordingcheck completed, returning 0
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'MixMonitor'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-record-enable:999] MixMonitor("Local/5001@from-internal-cd25,2", "-1153809527.21.wav|b") in new stack
Jul 25 16:38:47 DEBUG[6742] channel.c: Spy MixMonitor added to channel Local/5001@from-internal-cd25,2
Jul 25 16:38:47 DEBUG[6742] pbx.c: Expression result is '1'
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'GotoIf'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-exten-vm:8] GotoIf("Local/5001@from-internal-cd25,2", "1?dolocaldial|1") in new stack
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Goto (macro-exten-vm,dolocaldial,1)
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Macro'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [dolocaldial@macro-exten-vm:1] Macro("Local/5001@from-internal-cd25,2", "dial|||5001") in new stack
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'AGI'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-dial:1] AGI("Local/5001@from-internal-cd25,2", "dialparties.agi") in new stack
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jul 25 16:38:47 VERBOSE[6745] logger.c:   == Begin MixMonitor Recording Local/5001@from-internal-cd25,2
Jul 25 16:38:47 VERBOSE[6742] logger.c:   dialparties.agi: Starting New Dialparties.agi
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: priority is 1
Jul 25 16:38:47 VERBOSE[6742] logger.c:   dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
Jul 25 16:38:47 VERBOSE[6742] logger.c:   dialparties.agi: Methodology of ring is  'none'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: Added extension 5001 to extension map
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CF'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: Extension 5001 cf is disabled
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'DND'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: Extension 5001 do not disturb is disabled
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CW'
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CFB'
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CFU'
Jul 25 16:38:47 DEBUG[6747] manager.c: Manager received command 'login'
Jul 25 16:38:47 DEBUG[6747] config.c: Parsing /etc/asterisk/manager.conf
Jul 25 16:38:47 DEBUG[6747] config.c: Parsing /etc/asterisk/manager_custom.conf
Jul 25 16:38:47 WARNING[6747] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of manager_custom.conf
Jul 25 16:38:47 DEBUG[6747] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jul 25 16:38:47 DEBUG[6747] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jul 25 16:38:47 DEBUG[6747] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Jul 25 16:38:47 DEBUG[6747] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Jul 25 16:38:47 VERBOSE[6747] logger.c:   == Manager 'admin' logged on from 127.0.0.1
Jul 25 16:38:47 DEBUG[6747] manager.c: Manager received command 'ExtensionState'
Jul 25 16:38:47 DEBUG[6747] manager.c: Manager received command 'Logoff'
Jul 25 16:38:47 VERBOSE[6747] logger.c:   == Manager 'admin' logged off from 127.0.0.1
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: Checking CW and CFB status for extension 5001
Jul 25 16:38:47 DEBUG[6742] db.c: Unable to find key '5001' in family 'CALLTRACE'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     --  dialparties.agi: DbDel CALLTRACE/5001 - Caller ID is not defined
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- AGI Script dialparties.agi completed, returning 0
Jul 25 16:38:47 DEBUG[6742] pbx.c: Launching 'Dial'
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Executing [s@macro-dial:10] Dial("Local/5001@from-internal-cd25,2", "SIP/5001||") in new stack
Jul 25 16:38:47 DEBUG[6742] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
Jul 25 16:38:47 DEBUG[6742] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Jul 25 16:38:47 DEBUG[6742] chan_sip.c: Setting NAT on RTP to Off
Jul 25 16:38:47 DEBUG[6742] rtp.c: Channel 'Local/5001@from-internal-cd25,2' has no RTP, not doing anything
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-dial-s-10.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable MACRO_DEPTH.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable AGISTATUS.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable ds.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-dial-s-1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable ARG3.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable ARG2.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable ARG1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable MACRO_PRIORITY.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable MACRO_CONTEXT.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable MACRO_EXTEN.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-dolocaldial-1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-8.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable MIXMONITOR_FILENAME.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-record-enable-s-999.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable CALLFILENAME.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-record-enable-s-4.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-record-enable-s-1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-7.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable RT.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-6.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable CFUEXT.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-5.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable EXTTOCALL.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-4.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable VMBOX.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-3.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable FROMCONTEXT.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-2.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-user-callerid-s-9.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-user-callerid-s-1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-macro-exten-vm-s-1.
Jul 25 16:38:47 DEBUG[6742] channel.c: Not copying variable STACK-from-internal-5001-1.
Jul 25 16:38:47 DEBUG[6742] chan_sip.c: Outgoing Call for 5001
Jul 25 16:38:47 DEBUG[6742] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
Jul 25 16:38:47 VERBOSE[6742] logger.c:     -- Called 5001
Jul 25 16:38:47 DEBUG[6742] channel.c: Set channel SIP/5001-08692840 to read format ulaw
Jul 25 16:38:47 DEBUG[6742] channel.c: Set channel Local/5001@from-internal-cd25,2 to write format ulaw
Jul 25 16:38:47 DEBUG[6742] channel.c: Set channel Local/5001@from-internal-cd25,2 to read format ulaw
Jul 25 16:38:47 DEBUG[6742] channel.c: Set channel SIP/5001-08692840 to write format ulaw
Jul 25 16:38:47 DEBUG[5078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '12d3638f179866b179b1f8536e31514f@192.168.1.16' Request 102: Found
Jul 25 16:38:48 DEBUG[5078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '12d3638f179866b179b1f8536e31514f@192.168.1.16' Request 102: Found
Jul 25 16:38:48 VERBOSE[6742] logger.c:     -- SIP/5001-08692840 is ringing
Jul 25 16:38:48 DEBUG[6742] rtp.c: Channel 'Local/5001@from-internal-cd25,2' has no RTP, not doing anything
Jul 25 16:38:48 VERBOSE[6729] logger.c:     -- Local/5001@from-internal-cd25,1 is ringing
Jul 25 16:38:48 DEBUG[6748] app_queue.c: Device 'SIP/5001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul 25 16:38:49 DEBUG[5078] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
Jul 25 16:38:49 DEBUG[5078] chan_sip.c: Stopping retransmission on '6e5d63c80724bf900d993f4c14abb520@192.168.1.16' of Request 102: Match Not Found