My sip show peers:
=========================================================================
Connected to Asterisk 1.2.14 currently running on prxyafr (pid = 15232)
Verbosity was 0 and is now 12
prxyafr*CLI> sip show peers
Name/username Host Dyn Nat ACL Port Status
115 (Unspecified) D N 0 UNKNOWN
114 (Unspecified) D N 0 UNKNOWN
113 (Unspecified) D N 0 UNKNOWN
112 (Unspecified) D N 0 UNKNOWN
111 (Unspecified) D N 0 UNKNOWN
110 (Unspecified) D N 0 UNKNOWN
109 (Unspecified) D N 0 UNKNOWN
108 (Unspecified) D N 0 UNKNOWN
107 (Unspecified) D N 0 UNKNOWN
106/106 200.93.220.7 D N 5060 OK (282 ms)
105/105 200.58.211.225 D N 60089 OK (113 ms)
104 (Unspecified) D N 0 UNKNOWN
103 (Unspecified) D N 0 UNKNOWN
102 (Unspecified) D N 0 UNKNOWN
101 (Unspecified) D N 0 UNKNOWN
100 (Unspecified) D N 0 UNKNOWN
16 sip peers [2 online , 14 offline]
This is the log, first calling to a non registered extension (101):
Feb 9 08:44:42 DEBUG[15242] chan_sip.c: Stopping retransmission on '15eca8c339414a4b1af1e1c75ed2f97e@190.24.227.62' of Request 102: Match Found
Feb 9 08:44:44 DEBUG[15242] chan_sip.c: Stopping retransmission on '581d196749530c0a0aca8bd549f4e4e4@190.24.227.62' of Request 102: Match Found
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: Setting NAT on RTP to 524288
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: Stopping retransmission on '3046286146@200.93.220.7' of Response 1: Match Found
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: Setting NAT on RTP to 524288
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: Checking SIP call limits for device 106
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: build_route: Contact hop: Guillermo Salas M
Feb 9 08:44:49 DEBUG[15237] channel.c: Avoiding initial deadlock for 'SIP/106-08176ae8'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "exten-vm|101|101") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "user-callerid") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is 'device'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "user-callerid: device 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?report") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?start") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "REALCALLERIDNUM=106") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "REALCALLERIDNUM is 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "AMPUSER=106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is 'Extension 106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "AMPUSERCIDNAME=Extension 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?report") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "CALLERID(all)=Extension 106 <106>") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "REALCALLERIDNUM=106") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "TTL: ARG1: 101") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?continue") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '-1'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '64'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "_TTL=64") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "1?continue") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-user-callerid,s,21)
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "Using CallerID "Extension 106" <106>") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "FROMCONTEXT=exten-vm") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "VMBOX=101") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "EXTTOCALL=101") in new stack
Feb 9 08:44:49 DEBUG[15306] db.c: Unable to find key '101' in family 'CFU'
Feb 9 08:44:49 DEBUG[15306] func_db.c: DB: CFU/101 not found in database.
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is ''
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "CFUEXT=") in new stack
Feb 9 08:44:49 DEBUG[15306] db.c: Unable to find key '101' in family 'CFB'
Feb 9 08:44:49 DEBUG[15306] func_db.c: DB: CFB/101 not found in database.
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is ''
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "CFBEXT=") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '15'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "RT=15") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "record-enable|101|IN") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?2:4") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-record-enable,s,4)
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing DeadAGI("SIP/106-08176ae8", "recordingcheck|20070209-084449|1171028689.2") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- AGI Script recordingcheck completed, returning 0
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "No recording needed") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "dial|15|tr|101") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing DeadAGI("SIP/106-08176ae8", "dialparties.agi") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- AGI Script dialparties.agi completed, returning 0
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "Returned from dialparties with no extensions to call") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "DIALSTATUS is ") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GosubIf("SIP/106-08176ae8", "0?docfu|1") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GosubIf("SIP/106-08176ae8", "0?docfb|1") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "Voicemail is 101") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?s-|1") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "Sending to Voicemail box 101") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "vm|101|") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "user-callerid|SKIPTTL") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is 'Extension 106'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "user-callerid: Extension 106 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?report") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "1?start") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-user-callerid,s,5)
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "REALCALLERIDNUM is 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "AMPUSER=106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is 'Extension 106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "AMPUSERCIDNAME=Extension 106") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?report") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Not taking any branch
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "CALLERID(all)=Extension 106 <106>") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "REALCALLERIDNUM=106") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "TTL: 64 ARG1: SKIPTTL") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "1?continue") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-user-callerid,s,21)
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "Using CallerID "Extension 106" <106>") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is ''
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "VMGAIN=") in new stack
Feb 9 08:44:49 WARNING[15306] func_db.c: DB requires an argument, DB(/)
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is ''
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '1'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "1?s-|1") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-vm,s-,1)
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Macro("SIP/106-08176ae8", "get-vmcontext|101") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Function result is 'default'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing Set("SIP/106-08176ae8", "VMCONTEXT=default") in new stack
Feb 9 08:44:49 DEBUG[15306] pbx.c: Expression result is '0'
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing GotoIf("SIP/106-08176ae8", "0?200:300") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Goto (macro-get-vmcontext,s,300)
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing NoOp("SIP/106-08176ae8", "") in new stack
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Executing VoiceMail("SIP/106-08176ae8", "101@default|u") in new stack
Feb 9 08:44:49 DEBUG[15237] channel.c: Avoiding initial deadlock for 'SIP/106-08176ae8'
Feb 9 08:44:49 DEBUG[15306] app_voicemail.c: /var/spool/asterisk/voicemail/default/101/unavail doesn't exist, doing what we can
Feb 9 08:44:49 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:49 VERBOSE[15306] logger.c: -- Playing 'vm-theperson' (language 'es')
Feb 9 08:44:49 DEBUG[15242] chan_sip.c: Stopping retransmission on '3046286146@200.93.220.7' of Response 2: Match Found
Feb 9 08:44:50 DEBUG[15306] chan_sip.c: Oooh, format changed to 8
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:51 VERBOSE[15306] logger.c: -- Playing 'digits/1' (language 'es')
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:51 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:51 VERBOSE[15306] logger.c: -- Playing 'digits/0' (language 'es')
Feb 9 08:44:52 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:52 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:52 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:52 VERBOSE[15306] logger.c: -- Playing 'digits/1' (language 'es')
Feb 9 08:44:53 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:53 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:53 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:53 VERBOSE[15306] logger.c: -- Playing 'vm-isunavail' (language 'es')
Feb 9 08:44:54 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:54 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:54 DEBUG[15306] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:44:54 VERBOSE[15306] logger.c: -- Playing 'vm-intro' (language 'es')
Feb 9 08:44:56 VERBOSE[15306] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-08176ae8' in macro 'vm'
Feb 9 08:44:56 VERBOSE[15306] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-08176ae8' in macro 'exten-vm'
Feb 9 08:44:56 VERBOSE[15306] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-08176ae8'
Feb 9 08:44:56 DEBUG[15306] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:44:56 DEBUG[15306] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Feb 9 08:44:56 DEBUG[15306] 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 ('2007-02-09 08:44:49','\"Extension 106\" <106>','106','101','from-internal', 'SIP/106-08176ae8','','VoiceMail','101@default|u',7,7,'ANSWERED',3,'')
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '106'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '101'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is 'from-internal'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is 'SIP/106-08176ae8'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '(null)'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is 'VoiceMail'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '101@default|u'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '2007-02-09 08:44:49'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '2007-02-09 08:44:49'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '2007-02-09 08:44:56'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '7'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '7'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is 'ANSWERED'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is 'DOCUMENTATION'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '(null)'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '1171028689.2'
Feb 9 08:44:56 DEBUG[15306] pbx.c: Function result is '(null)'
Feb 9 08:44:56 DEBUG[15306] chan_sip.c: update_call_counter(106) - decrement call limit counter
Now when I call to another extension that is registered (105) takes me to the voice message:
Feb 9 08:45:04 DEBUG[15242] chan_sip.c: Setting NAT on RTP to 524288
Feb 9 08:45:05 DEBUG[15242] chan_sip.c: Stopping retransmission on '637586342@200.93.220.7' of Response 1: Match Found
Feb 9 08:45:05 DEBUG[15242] chan_sip.c: Setting NAT on RTP to 524288
Feb 9 08:45:05 DEBUG[15242] chan_sip.c: Checking SIP call limits for device 106
Feb 9 08:45:05 DEBUG[15242] chan_sip.c: build_route: Contact hop: Guillermo Salas M
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "exten-vm|105|105") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "user-callerid") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is 'device'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "user-callerid: device 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?report") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?start") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "REALCALLERIDNUM=106") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "REALCALLERIDNUM is 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "AMPUSER=106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is 'Extension 106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "AMPUSERCIDNAME=Extension 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?report") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "CALLERID(all)=Extension 106 <106>") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "REALCALLERIDNUM=106") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "TTL: ARG1: 105") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?continue") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '-1'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '64'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "_TTL=64") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "1?continue") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-user-callerid,s,21)
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "Using CallerID "Extension 106" <106>") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "FROMCONTEXT=exten-vm") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "VMBOX=105") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "EXTTOCALL=105") in new stack
Feb 9 08:45:05 DEBUG[15312] db.c: Unable to find key '105' in family 'CFU'
Feb 9 08:45:05 DEBUG[15312] func_db.c: DB: CFU/105 not found in database.
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is ''
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "CFUEXT=") in new stack
Feb 9 08:45:05 DEBUG[15312] db.c: Unable to find key '105' in family 'CFB'
Feb 9 08:45:05 DEBUG[15312] func_db.c: DB: CFB/105 not found in database.
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is ''
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "CFBEXT=") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '15'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "RT=15") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "record-enable|105|IN") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?2:4") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-record-enable,s,4)
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing DeadAGI("SIP/106-081cc738", "recordingcheck|20070209-084505|1171028705.3") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- AGI Script recordingcheck completed, returning 0
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "No recording needed") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "dial|15|tr|105") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing DeadAGI("SIP/106-081cc738", "dialparties.agi") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- AGI Script dialparties.agi completed, returning 0
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "Returned from dialparties with no extensions to call") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "DIALSTATUS is ") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GosubIf("SIP/106-081cc738", "0?docfu|1") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GosubIf("SIP/106-081cc738", "0?docfb|1") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "Voicemail is 105") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?s-|1") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "Sending to Voicemail box 105") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "vm|105|") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "user-callerid|SKIPTTL") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is 'Extension 106'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "user-callerid: Extension 106 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?report") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "1?start") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-user-callerid,s,5)
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "REALCALLERIDNUM is 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "AMPUSER=106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is 'Extension 106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "AMPUSERCIDNAME=Extension 106") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "0?report") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Not taking any branch
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "CALLERID(all)=Extension 106 <106>") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "REALCALLERIDNUM=106") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "TTL: 64 ARG1: SKIPTTL") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "1?continue") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-user-callerid,s,21)
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing NoOp("SIP/106-081cc738", "Using CallerID "Extension 106" <106>") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '0'
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is ''
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "VMGAIN=") in new stack
Feb 9 08:45:05 WARNING[15312] func_db.c: DB requires an argument, DB(/)
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is ''
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "1?s-|1") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-vm,s-,1)
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Macro("SIP/106-081cc738", "get-vmcontext|105") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Function result is ''
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "VMCONTEXT=") in new stack
Feb 9 08:45:05 DEBUG[15312] pbx.c: Expression result is '1'
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing GotoIf("SIP/106-081cc738", "1?200:300") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Goto (macro-get-vmcontext,s,200)
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing Set("SIP/106-081cc738", "VMCONTEXT=default") in new stack
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Executing VoiceMail("SIP/106-081cc738", "105@default|u") in new stack
Feb 9 08:45:05 DEBUG[15237] channel.c: Avoiding initial deadlock for 'SIP/106-081cc738'
Feb 9 08:45:05 DEBUG[15312] app_voicemail.c: /var/spool/asterisk/voicemail/default/105/unavail doesn't exist, doing what we can
Feb 9 08:45:05 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:05 VERBOSE[15312] logger.c: -- Playing 'vm-theperson' (language 'es')
Feb 9 08:45:05 DEBUG[15242] chan_sip.c: Stopping retransmission on '637586342@200.93.220.7' of Response 2: Match Found
Feb 9 08:45:05 DEBUG[15312] chan_sip.c: Oooh, format changed to 8
Feb 9 08:45:06 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:06 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:06 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:06 VERBOSE[15312] logger.c: -- Playing 'digits/1' (language 'es')
Feb 9 08:45:07 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:07 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:07 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:07 VERBOSE[15312] logger.c: -- Playing 'digits/0' (language 'es')
Feb 9 08:45:08 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:08 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:08 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:08 VERBOSE[15312] logger.c: -- Playing 'digits/5' (language 'es')
Feb 9 08:45:09 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:09 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:09 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:09 VERBOSE[15312] logger.c: -- Playing 'vm-isunavail' (language 'es')
Feb 9 08:45:10 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:10 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:10 DEBUG[15312] channel.c: Scheduling timer at 160 sample intervals
Feb 9 08:45:10 VERBOSE[15312] logger.c: -- Playing 'vm-intro' (language 'es')
Feb 9 08:45:15 VERBOSE[15312] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-081cc738' in macro 'vm'
Feb 9 08:45:15 VERBOSE[15312] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-081cc738' in macro 'exten-vm'
Feb 9 08:45:15 VERBOSE[15312] logger.c: == Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/106-081cc738'
Feb 9 08:45:15 DEBUG[15312] channel.c: Scheduling timer at 0 sample intervals
Feb 9 08:45:15 DEBUG[15312] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Feb 9 08:45:15 DEBUG[15312] 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 ('2007-02-09 08:45:05','\"Extension 106\" <106>','106','105','from-internal', 'SIP/106-081cc738','','VoiceMail','105@default|u',10,10,'ANSWERED',3,'')
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '"Extension 106" <106>'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '106'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '105'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is 'from-internal'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is 'SIP/106-081cc738'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '(null)'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is 'VoiceMail'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '105@default|u'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '2007-02-09 08:45:05'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '2007-02-09 08:45:05'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '2007-02-09 08:45:15'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '10'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '10'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is 'ANSWERED'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is 'DOCUMENTATION'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '(null)'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '1171028705.3'
Feb 9 08:45:15 DEBUG[15312] pbx.c: Function result is '(null)'
Feb 9 08:45:15 DEBUG[15312] chan_sip.c: update_call_counter(106) - decrement call limit counter
Feb 9 08:45:15 DEBUG[15312] chan_sip.c: update_call_counter(106) - decrement call limit counter