[Asterisk-Users] Extensions go straight to voicemail
Robin
robin at coptalk.com
Tue Sep 27 16:17:38 MST 2005
Hello,
I have setup a test server with asterisk/AMP and have several 7960's
connected to it. The asterisk server has a public ip and all the
7960's are behind nat'd routers. When I try to call from extension
to extension I get directed straight to voicemail. I do not have any
cards installed and instead direct everything to an Ondo server. I
have been told it's not an AMP problem, I'm just totally lost on
where to look for a solution.
I have noticed when running ztcfg -v I have 0 channels configured, do
I require some type of pseudo channels to make this work? If I dial
extension 2346 this is what my logfile looks like.
Thank you for any help,
Robin
<snip>
Sep 27 16:02:49 DEBUG[11596]: Setting NAT on RTP to 4
Sep 27 16:02:49 DEBUG[11596]: Stopping retransmission on
'00055eba-d677004e-4e1bc717-21d6c979 at 192.168.1.115' of Response 101: Found
Sep 27 16:02:49 DEBUG[11596]: Setting NAT on RTP to 4
Sep 27 16:02:49 DEBUG[11596]: Check for res for 2100
Sep 27 16:02:49 DEBUG[11596]: Call from user '2100' is 1 out of 0
Sep 27 16:02:49 DEBUG[11596]: build_route: Contact hop:
<sip:2100 at 192.168.1.115:5060>
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "exten-vm|2346 at default|2346") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "user-callerid") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
DBget("SIP/2100-a982", "AMPUSER=DEVICE/2100/user") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- DBget: varname=AMPUSER,
family=DEVICE, key=2100/user
Sep 27 16:02:49 VERBOSE[11596]: -- DBget: set variable AMPUSER to 2100
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
DBget("SIP/2100-a982", "AMPUSERCIDNAME=AMPUSER/2100/cidname") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- DBget: varname=AMPUSERCIDNAME,
family=AMPUSER, key=2100/cidname
Sep 27 16:02:49 VERBOSE[11596]: -- DBget: set variable
AMPUSERCIDNAME to Test1
Sep 27 16:02:49 DEBUG[11596]: Expression is '0'
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?5") in new stack
Sep 27 16:02:49 DEBUG[11596]: Not taking any branch
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
SetCallerID("SIP/2100-a982", "Test1 <2100>") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
NoOp("SIP/2100-a982", "Using CallerID Test1 <2100>") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
SetVar("SIP/2100-a982", "FROMCONTEXT=exten-vm") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "record-enable|2346|IN") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0 > 0?2:4") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Goto (macro-record-enable,s,4)
Sep 27 16:02:49 VERBOSE[11596]: -- Executing AGI("SIP/2100-a982",
"recordingcheck|20050927-160249|1127862169.19") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Launched AGI Script
/var/lib/asterisk/agi-bin/recordingcheck
Sep 27 16:02:49
VERBOSE[11596]: recordingcheck|20050927-160249|1127862169.19:
Inbound recording not enabled
Sep 27 16:02:49 VERBOSE[11596]: -- AGI Script recordingcheck
completed, returning 0
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
NoOp("SIP/2100-a982", "No recording needed") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "dial|15|tr|2346") in new stack
Sep 27 16:02:49 DEBUG[11596]: Expression is '0'
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?4:2") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Goto (macro-dial,s,2)
Sep 27 16:02:49 WARNING[11596]: ast_yyerror(): syntax error: syntax
error; Input:
!= ^
Sep 27 16:02:49 DEBUG[11596]: Expression is '0'
Sep 27 16:02:49 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?5:4") in new stack
Sep 27 16:02:49 VERBOSE[11596]: -- Goto (macro-dial,s,4)
Sep 27 16:02:49 VERBOSE[11596]: -- Executing AGI("SIP/2100-a982",
"dialparties.agi") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Launched AGI Script
/var/lib/asterisk/agi-bin/dialparties.agi
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: request =
dialparties.agi
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: priority = 4
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: extension = s
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: language = en
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: accountcode =
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: uniqueid =
1127862169.19
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: channel =
SIP/2100-a982
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: callerid =
Test1 <2100>
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: context = macro-dial
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: rdnis = unknown
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: type = SIP
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: enhanced = 0.0
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: dnid = 2346
Sep 27 16:02:50 VERBOSE[11596]: dialparties.agi: Caller ID is not set
Sep 27 16:02:50 VERBOSE[11596]: dialparties.agi: Methodology of
ring is 'none'
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: Added
extension 2346 to extension map
Sep 27 16:02:50 DEBUG[11596]: Unable to find key '2346' in family 'CF'
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: Extension
2346 cf is disabled
Sep 27 16:02:50 DEBUG[11596]: Unable to find key '2346' in family 'DND'
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: Extension
2346 do not disturb is disabled
Sep 27 16:02:50 DEBUG[11596]: Unable to find key '2346' in family 'CW'
Sep 27 16:02:50 DEBUG[11596]: Unable to find key '2346' in family 'CFB'
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: Checking CW
and CFB status for extension 2346
Sep 27 16:02:50 DEBUG[11596]: Manager received command 'Login'
Sep 27 16:02:50 VERBOSE[11596]: == Parsing
'/etc/asterisk/manager.conf': Sep 27 16:02:50 VERBOSE[11596]: ==
Parsing '/etc/asteri
sk/manager.conf': Found
Sep 27 16:02:50 VERBOSE[11596]: == Parsing
'/etc/asterisk/manager_custom.conf': Sep 27 16:02:50
VERBOSE[11596]: == Parsing '/etc
/asterisk/manager_custom.conf': Not found (No such file or directory)
Sep 27 16:02:50 DEBUG[11596]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Sep 27 16:02:50 DEBUG[11596]: 127.0.0.1/255.255.255.0/255.255.255.0
appended to acl for peer
Sep 27 16:02:50 DEBUG[11596]: ##### Testing 127.0.0.1 with 0.0.0.0
Sep 27 16:02:50 DEBUG[11596]: ##### Testing 127.0.0.1 with 127.0.0.0
Sep 27 16:02:50 VERBOSE[11596]: == Manager 'admin' logged on from 127.0.0.1
Sep 27 16:02:50 DEBUG[11596]: Manager received command 'ExtensionState'
Sep 27 16:02:50 DEBUG[11596]: Manager received command 'Logoff'
Sep 27 16:02:50 VERBOSE[11596]: dialparties.agi: Extension 2346 is
available...skipping checks
Sep 27 16:02:50 VERBOSE[11596]: == Manager 'admin' logged off from 127.0.0.1
Sep 27 16:02:50 DEBUG[11596]: Unable to find key '2346' in family 'CALLTRACE'
Sep 27 16:02:50 VERBOSE[11596]: -- dialparties.agi: DbDel
CALLTRACE/2346 - Caller ID is not defined
Sep 27 16:02:50 VERBOSE[11596]: -- AGI Script dialparties.agi
completed, returning 0
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
Dial("SIP/2100-a982", "SIP/2346|15|tr") in new stack
Sep 27 16:02:50 DEBUG[11596]: SIMPLE DIAL (NO URL)
Sep 27 16:02:50 DEBUG[11596]: Setting NAT on RTP to 4
Sep 27 16:02:50 DEBUG[11596]: Outgoing Call for 2346
Sep 27 16:02:50 DEBUG[11596]: Call from user '2346' is 1 out of 0
Sep 27 16:02:50 VERBOSE[11596]: -- Called 2346
Sep 27 16:02:50 DEBUG[11596]: Acked pending invite 102
Sep 27 16:02:50 DEBUG[11596]: Stopping retransmission on
'1d2443b8564febb567d70868174a755c at 69.67.128.128' of Request 102: Found
Sep 27 16:02:50 VERBOSE[11596]: -- Got SIP response 404 "Not
Found" back from 69.67.128.221
Sep 27 16:02:50 VERBOSE[11596]: -- SIP/2346-1a14 is circuit-busy
Sep 27 16:02:50 DEBUG[11596]: update_user_counter(2346) - decrement
outUse counter
Sep 27 16:02:50 VERBOSE[11596]: == Everyone is busy/congested at this time
Sep 27 16:02:50 DEBUG[11596]: Exiting with DIALSTATUS=CONGESTION.
Sep 27 16:02:50 DEBUG[11596]: Expression is '0'
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?s-CONGESTION|1") in new stack
Sep 27 16:02:50 DEBUG[11596]: Not taking any branch
Sep 27 16:02:50 DEBUG[11596]: Expression is '0'
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?s-CONGESTION|1") in new stack
Sep 27 16:02:50 DEBUG[11596]: Not taking any branch
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
NoOp("SIP/2100-a982", "Sending to Voicemail box 2346") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "vm|2346 at default|CONGESTION") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "user-callerid") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
DBget("SIP/2100-a982", "AMPUSER=DEVICE/2100/user") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- DBget: varname=AMPUSER,
family=DEVICE, key=2100/user
Sep 27 16:02:50 VERBOSE[11596]: -- DBget: set variable AMPUSER to 2100
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
DBget("SIP/2100-a982", "AMPUSERCIDNAME=AMPUSER/2100/cidname") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- DBget: varname=AMPUSERCIDNAME,
family=AMPUSER, key=2100/cidname
Sep 27 16:02:50 VERBOSE[11596]: -- DBget: set variable
AMPUSERCIDNAME to Test1
Sep 27 16:02:50 DEBUG[11596]: Expression is '0'
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
GotoIf("SIP/2100-a982", "0?5") in new stack
Sep 27 16:02:50 DEBUG[11596]: Not taking any branch
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
SetCallerID("SIP/2100-a982", "Test1 <2100>") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
NoOp("SIP/2100-a982", "Using CallerID Test1 <2100>") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
Goto("SIP/2100-a982", "s-CONGESTION|1") in new stack
Sep 27 16:02:50 VERBOSE[11596]: -- Goto (macro-vm,s-CONGESTION,1)
Sep 27 16:02:50 VERBOSE[11596]: -- Executing
VoiceMail("SIP/2100-a982", "u2346 at default") in new stack
Sep 27 16:02:50 DEBUG[11596]: voicemail/default/2346/unavail doesn't
exist, doing what we can
Sep 27 16:02:50 DEBUG[11596]: Ooh, format changed from unknown to ulaw
Sep 27 16:02:50 VERBOSE[11596]: -- Playing 'vm-theperson' (language 'en')
Sep 27 16:02:50 DEBUG[11596]: Stopping retransmission on
'00055eba-d677004e-4e1bc717-21d6c979 at 192.168.1.115' of Response 102: Found
Sep 27 16:02:50 DEBUG[11596]: RTP NAT: Using address 69.67.128.221:24360
Sep 27 16:02:51 VERBOSE[11596]: -- Playing 'digits/2' (language 'en')
Sep 27 16:02:52 VERBOSE[11596]: -- Playing 'digits/3' (language 'en')
Sep 27 16:02:53 VERBOSE[11596]: -- Playing 'digits/4' (language 'en')
Sep 27 16:02:53 DEBUG[11596]: Stopping retransmission on
'00c6d39804111d997f7300b71a4bc271 at 69.67.1128.128' of Request 102: Found
Sep 27 16:02:53 VERBOSE[11596]: -- Playing 'digits/6' (language 'en')
Sep 27 16:02:54 VERBOSE[11596]: -- Playing 'vm-isunavail' (language 'en')
Sep 27 16:02:55 VERBOSE[11596]: -- Playing 'vm-intro' (language 'en')
Sep 27 16:03:00 VERBOSE[11596]: -- Playing 'beep' (language 'en')
Sep 27 16:03:01 DEBUG[11596]: Locked path
'/var/spool/asterisk/voicemail/default/2346/INBOX'
Sep 27 16:03:01 VERBOSE[11596]: -- Recording the message
Sep 27 16:03:01 DEBUG[11596]: play_and_record: <None>,
/var/spool/asterisk/voicemail/default/2346/INBOX/msg0001, 'wav49|wav'
Sep 27 16:03:01 DEBUG[11596]: Recording Formats: sfmts=wav49
Sep 27 16:03:01 VERBOSE[11596]: -- x=0, open
writing: /var/spool/asterisk/voicemail/default/2346/INBOX/msg0001
format: wav49, 0
x9c38080
Sep 27 16:03:01 VERBOSE[11596]: -- x=1, open
writing: /var/spool/asterisk/voicemail/default/2346/INBOX/msg0001
format: wav, 0x9
c383d0
Sep 27 16:03:01 DEBUG[11596]: Unlocked path
'/var/spool/asterisk/voicemail/default/2346/INBOX'
Sep 27 16:03:04 VERBOSE[11596]: -- User hung up
Sep 27 16:03:04 DEBUG[11596]: Attaching file
'/var/spool/asterisk/voicemail/default/2346/INBOX/msg0001', format
'WAV', uservm is '0'
, global is -1
Sep 27 16:03:04 DEBUG[11596]: Sent mail to robin at coptalk.com with
command '/usr/sbin/sendmail -t'
Sep 27 16:03:04 VERBOSE[11596]: == Spawn extension (macro-vm,
s-CONGESTION, 1) exited non-zero on 'SIP/2100-a982' in macro 'vm'
Sep 27 16:03:04 VERBOSE[11596]: == Spawn extension (macro-exten-vm,
s, 8) exited non-zero on 'SIP/2100-a982' in macro 'exten-vm'
Sep 27 16:03:04 VERBOSE[11596]: == Spawn extension (from-internal,
2346, 1) exited non-zero on 'SIP/2100-a982'
Sep 27 16:03:04 VERBOSE[11596]: -- Executing
Macro("SIP/2100-a982", "hangupcall") in new stack
Sep 27 16:03:04 VERBOSE[11596]: -- Executing
ResetCDR("SIP/2100-a982", "w") in new stack
Sep 27 16:03:04 DEBUG[11596]: cdr_mysql: inserting a CDR record.
Sep 27 16:03:04 DEBUG[11596]: 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 ('2005-09-27 16:02:49','Test1 <2100>','2100','
2346','from-internal',
'SIP/2100-a982','SIP/2346-1a14','ResetCDR','w',15,14,'ANSWERED',3,'','1127862169.19')
Sep 27 16:03:04 VERBOSE[11596]: -- Executing
NoCDR("SIP/2100-a982", "") in new stack
Sep 27 16:03:04 WARNING[11596]: CDR on channel 'SIP/2100-a982' not posted
Sep 27 16:03:04 WARNING[11596]: CDR on channel 'SIP/2100-a982' lacks end
Sep 27 16:03:04 VERBOSE[11596]: -- Executing
Wait("SIP/2100-a982", "5") in new stack
Sep 27 16:03:04 VERBOSE[11596]: == Spawn extension
(macro-hangupcall, s, 3) exited non-zero on 'SIP/2100-a982' in macro 'hangupcal
l'
Sep 27 16:03:04 VERBOSE[11596]: == Spawn extension (from-internal,
h, 1) exited non-zero on 'SIP/2100-a982'
Sep 27 16:03:04 DEBUG[11596]: update_user_counter(2100) - decrement
inUse counter
Sep 27 16:03:06 DEBUG[11596]: Setting NAT on RTP to 4
Sep 27 16:03:06 DEBUG[11596]: Stopping retransmission on
'1907076f59eab59629b7cf8130517ccb at 69.67.128.128' of Request 102: Found
Sep 27 16:03:06 VERBOSE[11596]: -- Got SIP response 404 "Not
Found" back from 69.67.128.221
Sep 27 16:03:13 DEBUG[11596]: Stopping retransmission on
'0b45c5f47058c96a044d06680f56e38d at 69.67.128.128' of Request 102: Found
</snip>
More information about the asterisk-users
mailing list