18 thoughts on - Voicemail Asking For Login

• –Apple-Mail=_8DFFDFB4-4974-4FDC-AE62-C331D68D5D7F
  Content-Transfer-Encoding: quoted-printable Content-Type: text/plain;
  charset=us-ascii

  Hi D’Arcy

  Try this:

  asterisk -r core set verbose 10
  [get user to trigger fault]
  [examine console output, and post to list if still unclear]

  If you don’t solve it yourself, then we’ll be able to help further once we’ve seen the output.

  HTH,

  Pete

  –Apple-Mail=_8DFFDFB4-4974-4FDC-AE62-C331D68D5D7F
  Content-Transfer-Encoding: quoted-printable Content-Type: text/html;
  charset=us-ascii

  Hi D’Arcy

  
  

  On 18/04/2017, at 5:17 am, D’Arcy Cain <darcy@VybeNetworks.com> wrote:

  
  

  <snip>

  One user (that we know of so far) has a different experience.  In that case they are asked for a mailbox number first.  <snip>
  

  
  

  I have tried searching for this issue but nothing seems to apply.  Most discussions are about “*97” vs. “*98”.  Can anyone suggest another field of enquiry?
  

  
  

  Try this:

  
  

  asterisk -r

  core set verbose 10

  [get user to trigger fault]

  [examine console output, and post to list if still unclear]

  
  

  If you don’t solve it yourself, then we’ll be able to help further once we’ve seen the output.

  
  

  HTH,

  
  

  Pete

  
  

  
  

  
  –Apple-Mail=_8DFFDFB4-4974-4FDC-AE62-C331D68D5D7F

• I can’t see much more than at my previous debug level but here it is anyway. Due to line wrapping I added “<<<" to the end of each line in case it is not clear where the actual line endings are. “Alex Chernyshev” <4164251212> going into voice mail for stocktrans2<<< -- Executing [stocktrans2@LocalSets:19] Set("SIP/alex-00000175", "_ACCOUNT=stocktrans2") in new stack<<< -- Executing [stocktrans2@LocalSets:20] VoiceMail("SIP/alex-00000175", "stocktrans2@VoiceMail,u") in new stack<<< > 0x7f7fea5dc000 — Probation passed – setting RTP source address to 72.143.94.110:28503<<< -- Playing
  ‘/var/spool/asterisk/voicemail/VoiceMail/stocktrans2/unavail.gsm’
  (language ‘en’)<<< > 0x7f7fea5dc000 — Probation passed – setting RTP source address to 72.143.94.110:28503<<< [Apr 18 11:45:38] DTMF[-1][C-0004c47b]: channel.c:4215 __ast_read: DTMF begin '*' received on SIP/alex-00000175<<< [Apr 18 11:45:38] DTMF[-1][C-0004c47b]: channel.c:4219 __ast_read: DTMF begin ignored '*' on SIP/alex-00000175<<< [Apr 18 11:45:38] DTMF[-1][C-0004c47b]: channel.c:4129 __ast_read: DTMF end '*' received on SIP/alex-00000175, duration 160 ms<<< [Apr 18 11:45:38] DTMF[-1][C-0004c47b]: channel.c:4199 __ast_read: DTMF end passthrough '*' on SIP/alex-00000175<<< -- Executing [a@LocalSets:1] Verbose("SIP/alex-00000175", "stocktrans2 entering mailbox") in new stack<<< stocktrans2 entering mailbox<<< -- Executing [a@LocalSets:2] Set("SIP/alex-00000175", "CDR(userfield)=stocktrans2") in new stack<<< -- Executing [a@LocalSets:3] VoiceMailMain("SIP/alex-00000175", "stocktrans2@VoiceMail") in new stack<<< -- Playing ‘vm-login.gsm’ (language ‘en’)<<< [Apr 18 11:45:49] WARNING[-1][C-0004c47b]: app_voicemail.c:10627 vm_authenticate: Couldn't read username<<< Everything looks the same as another one that works except for two things. The one that works doesn’t have the “Probation passed” lines. I am not sure if that is even part of this call. The other is the line with “Playing ‘vm-login.gsm'” in it. at that point the working one has this: — Playing ‘vm-password.gsm’ (language ‘en’)

  Not sure if that’s useful information since it just describes the original issue – that it asks for a login instead of a password.

• –Apple-Mail=_631B79C4-1957-4F54-9622-CA6E23FD4092
  Content-Transfer-Encoding: quoted-printable Content-Type: text/plain;
  charset=us-ascii

  Presumably also the line containing ‘vm_authenticate: Couldn’t read username’ also doesn’t appear in the output on a working mailbox either?

  I think that’s the place to concentrate your efforts.
  
  It shows shortly after the attempt by VoiceMailMain to enter mailbox ‘stocktrans2’ in context ‘VoiceMail’. Does this mailbox exist?

  Can you show the equivalent line from a working mailbox (so we can see if it also uses the context ‘VoiceMail’, or maybe something else instead, like ‘default’?).

  Pete

  –Apple-Mail=_631B79C4-1957-4F54-9622-CA6E23FD4092
  Content-Transfer-Encoding: quoted-printable Content-Type: text/html;
  charset=us-ascii

  On 19/04/2017, at 7:58 am, D’Arcy Cain <darcy@VybeNetworks.com> wrote:

  
  

  <snip>
  

  Everything looks the same as another one that works except for two things.  The one that works doesn’t have the “Probation passed” lines. I am not sure if that is even part of this call.  The other is the line with “Playing ‘vm-login.gsm'” in it.  at that point the working one has this:
  

  <snip>

  
  

  Presumably also the line containing ‘vm_authenticate: Couldn’t read username’ also doesn’t appear in the output on a working mailbox either?

  
  

  I think that’s the place to concentrate your efforts.

  

  It shows shortly after the attempt by VoiceMailMain to enter mailbox ‘stocktrans2’ in context ‘VoiceMail’. Does this mailbox exist?

  
  

  Can you show the equivalent line from a working mailbox (so we can see if it also uses the context ‘VoiceMail’, or maybe something else instead, like ‘default’?).

  
  

  Pete

  
  

  
  –Apple-Mail=_631B79C4-1957-4F54-9622-CA6E23FD4092

• Hi Darcy,

  What Pete think is correct.

  Maybe excecuting the following command at Asterisk console, will help you:

  asterisk> voicemail show users

  And you will get a list of all mailbox configured in your system. Search for the user with problems.

  Finally, in the Asterisk wiki you can find more info:

  https://wiki.asterisk.org/wiki/display/AST/Configuring+Voice+Mail+Boxes

  Cheers

  El 18 abr. 2017 21:18, “Pete Mundy” escribió:

  Everything looks the same as another one that works except for two things. The one that works doesn’t have the “Probation passed” lines. I am not sure if that is even part of this call. The other is the line with “Playing
  ‘vm-login.gsm'” in it. at that point the working one has this:

  Presumably also the line containing ‘vm_authenticate: Couldn’t read username’ also doesn’t appear in the output on a working mailbox either?

  I think that’s the place to concentrate your efforts. It shows shortly after the attempt by VoiceMailMain to enter mailbox
  ‘stocktrans2’ in context ‘VoiceMail’. Does this mailbox exist?

  Can you show the equivalent line from a working mailbox (so we can see if it also uses the context ‘VoiceMail’, or maybe something else instead, like
  ‘default’?).

  Pete

• VoiceMail stocktrans2 Angelica Douglas 12

  Definitely there. In fact, I generate all the configs from a database with a script so I would be very surprised if one user was different from another.

• Exactly. Since it is not all digits it can’t be entered.

  Yes.

  “” <6477190146> going into voice mail for alex<<< -- Executing [alex@LocalSets:19] Set("SIP/thinktel-00000181", "_ACCOUNT=alex") in new stack<<< -- Executing [alex@LocalSets:20] VoiceMail("SIP/thinktel-00000181", "alex@VoiceMail,u") in new stack<<< -- Playing
  ‘/var/spool/asterisk/voicemail/VoiceMail/alex/unavail.gsm’ (language
  ‘en’)<<< [Apr 18 11:56:47] DTMF[-1][C-0004c485]: channel.c:4215 __ast_read: DTMF begin '*' received on SIP/thinktel-00000181<<< [Apr 18 11:56:47] DTMF[-1][C-0004c485]: channel.c:4219 __ast_read: DTMF begin ignored '*' on SIP/thinktel-00000181<<< [Apr 18 11:56:48] DTMF[-1][C-0004c485]: channel.c:4129 __ast_read: DTMF end '*' received on SIP/thinktel-00000181, duration 280 ms<<< [Apr 18 11:56:48] DTMF[-1][C-0004c485]: channel.c:4199 __ast_read: DTMF end passthrough '*' on SIP/thinktel-00000181<<< -- Executing [a@LocalSets:1] Verbose("SIP/thinktel-00000181", "alex entering mailbox") in new stack<<< alex entering mailbox<<< -- Executing [a@LocalSets:2] Set("SIP/thinktel-00000181", "CDR(userfield)=alex") in new stack<<< -- Executing [a@LocalSets:3] VoiceMailMain("SIP/thinktel-00000181", "alex@VoiceMail") in new stack<<< -- Playing ‘vm-password.gsm’ (language ‘en’)<<< [Apr 18 11:56:53] WARNING[-1][C-0004c485]: app_voicemail.c:10671 vm_authenticate: Unable to read password<<< I hung up before entering the password but it does work when the user does it.

• Hmm… Above my pay grade I’m afraid! Looking at your ‘voicemail show users’ I can’t see why the vm_authenticate function is failing to read the username 🙁

  If I were any good at coding in C, I’d probably look inside app_voicemail.c around line number 10671 and see if I could determine how it reads the username and maybe throw some hacky debug output in there to try and determine at which point of that process it’s failing. But I’m no good at coding in that language, so will have to defer to others to help.

  Good work on sending through the console clipping and relevant info. Sorry I couldn’t resolve it for you.

  Anyone else got any other ideas?

  Pete

• > show users’ I can’t see why the vm_authenticate function is
  > failing to read the username 🙁

  I can answer that one. It’s because we can’t enter ‘stocktrans2’ from a telephone so we just hang up. The question is, why does it ask for the mailbox in the first place>

  > app_voicemail.c around line number 10671 and see if I could
  > determine how it reads the username and maybe throw some hacky
  ? debug output in there to try and determine at which point of
  > that process it’s failing. But I’m no good at coding in that
  > language, so will have to defer to others to help.

  I guess that’s my next stop. Luckily I have kept my C skills somewhat active as the chief maintainer for PyGreSQL. 🙂

• I fished this out of an old extensions.conf from a defunct project. It might be relevant to your use case:

  exten => 1571,1,NoOp(Call to 1571: voicemail retrieval)
  exten => 1571,n,AGI(lookup_caller_id.agi,${CALLERID(num)})
  exten => 1571,n,NoOp(CLID is ${clid})
  exten => 1571,n,VoiceMailMain(${clid},s)

  The AGI script `lookup_caller_id.agi` sets the variable ${clid} to the caller’s extension number, after which their mailbox is named (although there is no reason not to set another variable, such as ${mbox} to hold the mailbox if you want). In the call to voicemailmail() we specify this mailbox, and also use the `s` option to skip password checking (it was safe in this situation to assume that nobody had physical access to a phone who definitely should not have had access to its user’s voicemail messages).

  The upshot of this was, if you dialled 1571 from your own phone, then you got put straight through to your own voicemail, without logging in.

• I do something similar using *98.

  Yes and that works just fine for us. The problem is that we are trying to deal with the situation where someone calls themselves from another phone (internal or external) to pick up their messages. In every other case it asks for their password (which is always numeric) and goes into the VM. This one extension asks for a mailbox.

• This is just screaming “configuration mismatch” — or, possibly, “latent bug whereby things parsed in separate places should be treated the same, but are actually getting treated differently”.

  I think we are going to need to see your dialplan logic, and maybe your voicemail.conf, in order to work out what is different between this one user and all the others. You might even need to use `hd` to examine the files, just in case there is a stray non-printing character spoiling things.

• I really don’t want to be the “my system isn’t working so there must be a bug in Asterisk” guy but I am certainly starting to suspect it.

  Non-printing characters show up in vi so I would have seen that by now.

  Every extension is build by a script that takes information from the database and does substitutions which is what makes this so baffling. Every extension is built exactly the same way. Here are two voicemail entries, the failing one and mine that works. The only sanitation I did was for the password.

  stocktrans2 => 9999,Angelica Douglas,stocktrans2@Vex.Net darcy => 9999,Vybe Networks – D’Arcy,darcy@Vex.Net

  Here is the full dialplan for stocktrans2.

  exten => stocktrans2,1,Verbose(0,Entering extension stocktrans2)
  same => n,Goto(DialCell)
  same => n,GotoIf($[“x” = “x”]?DialAlt)

  same => n(DialAll),Verbose(0,${CALLERID(all)} Calling ${EXTEN} and ALL)
  same => n,Dial(SIP/stocktrans2&SIP/thinktel/&SIP/9999907084,30)
  same => n,Goto(VoiceMail)

  same => n(DialAlt),Verbose(0, ${CALLERID(all)} Calling ${EXTEN} and SoftPhone)
  same => n,Dial(SIP/stocktrans2&SIP/9999907084,30)
  same => n,Goto(VoiceMail)

  same => n(DialCell),GotoIf($[“x” = “x”]?DialDesk)
  same => n,GotoIf($[“${CALLERID(ani)}” = “”]?DialDesk)
  same => n,Verbose(0,${CALLERID(all)} Calling “${EXTEN}” and cell “”)
  same => n,Dial(SIP/stocktrans2&SIP/thinktel/,30)
  same => n,Goto(VoiceMail)

  same => n(DialDesk),Verbose(0,${CALLERID(all)} Calling ${EXTEN})
  same => n,Dial(SIP/stocktrans2,30)

  same => n(VoiceMail),Set(CDR(userfield)=VoiceMail)
  same => n,Verbose(0,${CALLERID(all)} going into voice mail for stocktrans2)
  same => n,Set(_ACCOUNT=stocktrans2)
  same => n,VoiceMail(stocktrans2@VoiceMail,u)
  same => n,Hangup()

  Here is mine.

  exten => darcy,1,Verbose(0,Entering extension darcy)
  same => n,GotoIf($[“${DEVICE_STATE(SIP/9999901001)}” “UNAVAILABLE”]?DialCell)
  same => n,GotoIf($[“x4168035991” = “x”]?DialAlt)

  same => n(DialAll),Verbose(0,${CALLERID(all)} Calling ${EXTEN} and ALL)
  same => n,Dial(SIP/darcy&SIP/thinktel/4168035991&SIP/9999901001,30)
  same => n,Goto(VoiceMail)

  same => n(DialAlt),Verbose(0, ${CALLERID(all)} Calling ${EXTEN} and SoftPhone)
  same => n,Dial(SIP/darcy&SIP/9999901001,30)
  same => n,Goto(VoiceMail)

  same => n(DialCell),GotoIf($[“x4168035991” = “x”]?DialDesk)
  same => n,GotoIf($[“${CALLERID(ani)}” = “4168035991”]?DialDesk)
  same => n,Verbose(0,${CALLERID(all)} Calling “${EXTEN}” and cell
  “4168035991”)
  same => n,Dial(SIP/darcy&SIP/thinktel/4168035991,30)
  same => n,Goto(VoiceMail)

  same => n(DialDesk),Verbose(0,${CALLERID(all)} Calling ${EXTEN})
  same => n,Dial(SIP/darcy,30)

  same => n(VoiceMail),Set(CDR(userfield)=VoiceMail)
  same => n,Verbose(0,${CALLERID(all)} going into voice mail for darcy)
  same => n,Set(_ACCOUNT

• I reduced this to the following and I still have the error.

  exten => stocktrans2,1,Verbose(0,Entering extension stocktrans2)
  same => n(VoiceMail),Set(CDR(userfield)=VoiceMail)
  same => n,Verbose(0,${CALLERID(all)} going into voice mail for stocktrans2)
  same => n,VoiceMail(stocktrans2@VoiceMail,u)
  same => n,Hangup()

• O.K., so — assuming that extension “darcy” behaves properly if you simplify it similarly — nothing before there can be causing the problem.

  What is in your [VoiceMail] context? Are “stocktrans2” and “darcy” separate extensions, or is there a catch-all? What is in the “a” extension (which gets called when the * key is pressed) ?

• Actually, it also failed too when I reduced it. Turns out that that’s why I needed to set “_ACCOUNT”. Here is the actual reduced version for stocktrans2. It still fails but substituting “darcy” for “stocktrans2
  works OK.

  exten => stocktrans2,1,Verbose(0,Entering extension stocktrans2)
  same => n(VoiceMail),Set(CDR(userfield)=VoiceMail)
  same => n,Verbose(0,${CALLERID(all)} going into voice mail for stocktrans2)
  same => n,Set(_ACCOUNT=stocktrans2)
  same => n,VoiceMail(stocktrans2@VoiceMail,u)
  same => n,Hangup()

  Nothing in [VoiceMail] context except the mailboxes but this precedes the context:

  [general]
  attach=yes maxsilence
  maxlogins=3
  serveremail=NULL@Vex.Net format=wav49
  fromstring=Vybe Networks Voice Mail nextaftercmd=yes forcename=yes pollmailboxes=yes pollfreq=5

  emailbody

• I enable full log and run ‘core set debug 9’ before doing a pair of tests.

  (The full log is easier to grep than the console output.)

  Then compare a working vs stocktrans2 side by side.

  -JimC

• I did debug 10 and saved the console output into files which I compared side by side. No material difference.

• DC> I did debug 10 and saved the console output into files which I
  DC> compared side by side. No material difference.

  In that case I’d add more debug statements to apps/app_voicemail.c (in vm_exec()), including a log at the start of what is in *data and args.

  Looking at it, it only plays vm-whichbox when ast_strlen_zero(data), which implies that the args to Voicemail are not making it through.

  -JimC