Problem with voicemail - can't log in to mailbox

ichkata66 · May 14, 2009, 5:23pm

Hi guys,
We use FreePBX 2.5.1.1,asterisk 1.4.21.2 on Ubuntu Server 8.10 and have not had any problems until now.And the problem is that we can not listen to our voicemail… actually we can’t log in to mailbox from the softphone (we use X-lite). Like ususal, we type *97, and password after that… but automated voice says: Login incorrect ??? Here is log file:

[May 14 16:22:08] DEBUG[26901] chan_sip.c: Checking SIP call limits for device 108
[May 14 16:22:08] DEBUG[26901] chan_sip.c: Call from peer ‘108’ is 1 out of 50
[May 14 16:22:08] DEBUG[26901] devicestate.c: Notification of state change to be queued on device/channel SIP/108
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Changing state for SIP/108 - state 2 (In use)
[May 14 16:22:08] DEBUG[26881] app_queue.c: Device ‘SIP/108’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Checking if I can find provider for “Custom” - number: DND108
[May 14 16:22:08] DEBUG[26875] db.c: Unable to find key ‘DND108’ in family ‘CustomDevstate’
[May 14 16:22:08] DEBUG[26901] chan_sip.c: build_route: Contact hop: sip:[email protected]:19164
[May 14 16:22:08] DEBUG[26901] chan_sip.c: SIP/108-b753c588: New call is still down… Trying…
[May 14 16:22:08] DEBUG[26901] devicestate.c: Notification of state change to be queued on device/channel SIP/108-b753c588
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108-b753c588
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108-b753c588
[May 14 16:22:08] DEBUG[26901] devicestate.c: Notification of state change to be queued on device/channel SIP/108
[May 14 16:22:08] VERBOSE[28916] logger.c: – Executing [*97@from-internal:1] Answer(“SIP/108-b753c588”, “”) in new stack
[May 14 16:22:08] DEBUG[28916] devicestate.c: Notification of state change to be queued on device/channel SIP/108-b753c588
[May 14 16:22:08] DEBUG[28916] devicestate.c: Notification of state change to be queued on device/channel SIP/108
[May 14 16:22:08] DEBUG[28916] chan_sip.c: SIP answering channel: SIP/108-b753c588
[May 14 16:22:08] VERBOSE[28916] logger.c: – Executing [*97@from-internal:2] Wait(“SIP/108-b753c588”, “1”) in new stack
[May 14 16:22:08] DEBUG[26875] devicestate.c: Changing state for SIP/108-b753c588 - state 4 (Invalid)
[May 14 16:22:08] DEBUG[26881] app_queue.c: Device ‘SIP/108-b753c588’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Changing state for SIP/108 - state 2 (In use)
[May 14 16:22:08] DEBUG[26881] app_queue.c: Device ‘SIP/108’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Checking if I can find provider for “Custom” - number: DND108
[May 14 16:22:08] DEBUG[26875] db.c: Unable to find key ‘DND108’ in family ‘CustomDevstate’
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108-b753c588
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108-b753c588
[May 14 16:22:08] DEBUG[26875] devicestate.c: Changing state for SIP/108-b753c588 - state 4 (Invalid)
[May 14 16:22:08] DEBUG[26881] app_queue.c: Device ‘SIP/108-b753c588’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Changing state for SIP/108 - state 2 (In use)
[May 14 16:22:08] DEBUG[26881] app_queue.c: Device ‘SIP/108’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[May 14 16:22:08] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:08] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:08] DEBUG[26875] devicestate.c: Checking if I can find provider for “Custom” - number: DND108
[May 14 16:22:08] DEBUG[26875] db.c: Unable to find key ‘DND108’ in family ‘CustomDevstate’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [*97@from-internal:3] Macro(“SIP/108-b753c588”, “user-callerid|”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/108-b753c588”, “AMPUSER=108”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/108-b753c588”, “0?report”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/108-b753c588”, “1|Set|REALCALLERIDNUM=108”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/108-b753c588”, “AMPUSER=108”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘SipUser108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/108-b753c588”, “AMPUSERCIDNAME=SipUser108”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/108-b753c588”, “0?report”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/108-b753c588”, “AMPUSERCID=108”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/108-b753c588”, “CALLERID(all)=“SipUser108” <108>”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘108’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/108-b753c588”, “REALCALLERIDNUM=108”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/108-b753c588”, “0|Set|CHANNEL(language)=”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/108-b753c588”, “0?continue”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:12] Set(“SIP/108-b753c588”, “__TTL=64”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/108-b753c588”, “1?continue”) in new stack
[May 14 16:22:09] DEBUG[28916] pbx.c: Function result is ‘“SipUser108” <108>’
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/108-b753c588”, “Using CallerID “SipUser108” <108>”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [*97@from-internal:4] Macro(“SIP/108-b753c588”, “get-vmcontext|108”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-get-vmcontext:1] Set(“SIP/108-b753c588”, “VMCONTEXT=default”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/108-b753c588”, “0?200:300”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [s@macro-get-vmcontext:300] NoOp(“SIP/108-b753c588”, “”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [*97@from-internal:5] MailboxExists(“SIP/108-b753c588”, “108@default”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [*97@from-internal:6] GotoIf(“SIP/108-b753c588”, “1?mbexist”) in new stack
[May 14 16:22:09] VERBOSE[28916] logger.c: – Executing [*97@from-internal:106] VoiceMailMain(“SIP/108-b753c588”, “108@default”) in new stack
[May 14 16:22:09] DEBUG[28916] app_voicemail.c: Before find user for mailbox 108
[May 14 16:22:09] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format gsm
[May 14 16:22:09] VERBOSE[28916] logger.c: – <SIP/108-b753c588> Playing ‘vm-password’ (language ‘en’)
[May 14 16:22:10] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format ulaw
[May 14 16:22:20] VERBOSE[28916] logger.c: – Incorrect password ‘’ for user ‘108’ (context = default)
[May 14 16:22:20] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format gsm
[May 14 16:22:20] VERBOSE[28916] logger.c: – <SIP/108-b753c588> Playing ‘vm-incorrect’ (language ‘en’)
[May 14 16:22:22] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format ulaw
[May 14 16:22:22] DEBUG[28916] app_voicemail.c: Before find user for mailbox 108
[May 14 16:22:22] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format gsm
[May 14 16:22:22] VERBOSE[28916] logger.c: – <SIP/108-b753c588> Playing ‘vm-password’ (language ‘en’)
[May 14 16:22:23] DEBUG[28916] channel.c: Set channel SIP/108-b753c588 to write format ulaw
[May 14 16:22:28] DEBUG[28916] channel.c: Soft-Hanging up channel ‘SIP/108-b753c588’
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [h@from-internal:1] Macro(“SIP/108-b753c588”, “hangupcall”) in new stack
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/108-b753c588”, “vw”) in new stack
[May 14 16:22:28] DEBUG[28916] 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,userfield) VALUES (‘2009-05-14 16:22:08’,’“SipUser108” <108>’,‘108’,’*97’,‘from-internal’, ‘SIP/108-b753c588’,’’,‘VoiceMailMain’,‘108@default’,20,20,‘ANSWERED’,3,’’,’’)
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“SIP/108-b753c588”, “”) in new stack
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“SIP/108-b753c588”, “1?skiprg”) in new stack
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“SIP/108-b753c588”, “1?skipblkvm”) in new stack
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“SIP/108-b753c588”, “1?theend”) in new stack
[May 14 16:22:28] VERBOSE[28916] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“SIP/108-b753c588”, “”) in new stack
[May 14 16:22:28] DEBUG[28916] app_macro.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on ‘SIP/108-b753c588’ in macro ‘hangupcall’
[May 14 16:22:28] DEBUG[28916] pbx.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on ‘SIP/108-b753c588’
[May 14 16:22:28] VERBOSE[28916] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/108-b753c588’
[May 14 16:22:28] DEBUG[28916] channel.c: Hanging up channel ‘SIP/108-b753c588’
[May 14 16:22:28] DEBUG[28916] chan_sip.c: Hangup call SIP/108-b753c588, SIP callid ZTk2N2JhNmY4Y2NiNjI1Y2MzOTRhNjA3ZjYzNDA0NTI.)
[May 14 16:22:28] DEBUG[28916] chan_sip.c: Call from peer ‘108’ removed from call limit 50
[May 14 16:22:28] DEBUG[28916] devicestate.c: Notification of state change to be queued on device/channel SIP/108
[May 14 16:22:28] DEBUG[28916] devicestate.c: Notification of state change to be queued on device/channel SIP/108-b753c588
[May 14 16:22:28] DEBUG[28916] devicestate.c: Notification of state change to be queued on device/channel SIP/108
[May 14 16:22:28] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:28] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:28] DEBUG[26875] devicestate.c: Changing state for SIP/108 - state 1 (Not in use)
[May 14 16:22:28] DEBUG[26881] app_queue.c: Device ‘SIP/108’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[May 14 16:22:28] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:28] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:28] DEBUG[26875] devicestate.c: Checking if I can find provider for “Custom” - number: DND108
[May 14 16:22:28] DEBUG[26875] db.c: Unable to find key ‘DND108’ in family ‘CustomDevstate’
[May 14 16:22:28] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108-b753c588
[May 14 16:22:28] DEBUG[26875] chan_sip.c: Checking device state for peer 108-b753c588
[May 14 16:22:28] DEBUG[26875] devicestate.c: Changing state for SIP/108-b753c588 - state 4 (Invalid)
[May 14 16:22:28] DEBUG[26881] app_queue.c: Device ‘SIP/108-b753c588’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[May 14 16:22:28] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:28] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:28] DEBUG[26875] devicestate.c: Changing state for SIP/108 - state 1 (Not in use)
[May 14 16:22:28] DEBUG[26881] app_queue.c: Device ‘SIP/108’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[May 14 16:22:28] DEBUG[26875] devicestate.c: No provider found, checking channel drivers for SIP - 108
[May 14 16:22:28] DEBUG[26875] chan_sip.c: Checking device state for peer 108
[May 14 16:22:28] DEBUG[26875] devicestate.c: Checking if I can find provider for “Custom” - number: DND108
[May 14 16:22:28] DEBUG[26875] db.c: Unable to find key ‘DND108’ in family ‘CustomDevstate’

I’ve tried to change password, to change extensions (create new ones,enable disable voicemail… etc) but result is always the same.Permissions on the files and/or user that things are running under user asterisk and group asterisk.
This is my voicemail.conf generated from GUI:
[general]
format=wav49|gsm|wav
serveremail=asterisk
;[email protected]
; Should the email contain the voicemail as an attachment
attach=yes
; Maximum number of messages per folder. If not specified, a default value
; (100) is used. Maximum value for this option is 9999.
;maxmsg=100
; Maximum length of a voicemail message in seconds
;maxmessage=180
; Minimum length of a voicemail message in seconds for the message to be kept
; The default is no minimum.
;minmessage=3
; Maximum length of greetings in seconds
;maxgreet=60
; How many milliseconds to skip forward/back when rew/ff in message playback
skipms=3000
; How many seconds of silence before we end the recording
maxsilence=10
; Silence threshold (what we consider silence: the lower, the more sensitive)
silencethreshold=128
; Max number of failed login attempts
maxlogins=3

emaildateformat=%A, %B %d, %Y at %r
sendvoicemail=yes

[zonemessages]
eastern=America/New_York|‘vm-received’ Q ‘digits/at’ IMp
central=America/Chicago|‘vm-received’ Q ‘digits/at’ IMp
central24=America/Chicago|‘vm-received’ q ‘digits/at’ H N 'hours’
military=Zulu|‘vm-received’ q ‘digits/at’ H N ‘hours’ 'phonetic/z_p’
european=Europe/Copenhagen|‘vm-received’ a d b ‘digits/at’ HM

[default]
; Define maximum number of messages per folder for a particular context.
;maxmsg=50

;
; Mailboxes may be organized into multiple contexts for
; voicemail virtualhosting
;

Thank you for any help.

duncant123 · August 12, 2009, 10:26pm

This problem is also occuring for me - I have ubuntu LTS 8.0.4 asterisk 1.6.0.10 and Freepbx 2.5.1.0

The voicemail.conf file is being written with [] instead of [default] so the voicemail system can’t find the mailboxes. If I change it manually it works, if I write another context it changes it, but when I write it back to default using freepbx gui it goes back to [] in voicemail.conf

I have tried reinstalling freepbx and it didn’t do much, but I am guessing deleting the lot and reinstalling it may help

kodr · August 13, 2009, 5:29pm

I’m getting almost the exact same symptoms, except I don’t get the [] in voicemail.conf.

Here’s what I’ve noticed.

Everytime I create a new extension, I lose the ability to leave a voicemail or login to voicemail (for all users.) I can manually add the mailbox config in voicemail.conf and get things working, but a short time later, it stops working.

Running ‘voicemail show users’ returns no users defined, but after manually adding the mailboxes to voicemail.conf and a ‘voicemail reload’ I get a good list of mailboxes, and for a few minutes, voicemail works normally. Eventually, things quit working, and I have to do another ‘voicemail reload’.

I’m not familiar with where the voicemail configuration data is stored, or what type of event (other then creating a new extension) causes this data to be overwritten. FreePBX 2.5.1.5 Asterisk 1.6.1.1

kodr · August 13, 2009, 6:03pm

I take back part of the above comment.

Adding an extension causes the mailboxes to get ‘lost.’ Manually adding them to voicemail.conf allows access to the mail boxes again.

Once I manually add the mail boxes to voicemail.conf and reload, the mailboxes are fine until a new extension is created.

kimkhan · September 13, 2009, 11:19am

I create an extension. Extension is create with 201@default
My voicemail.conf file looks fine
But when I go into var/spool/asterisk/voicemail I only see the ‘device’ folder and I see the extensions in there with links which is supposed to be a link to the same user in the default folder. The default folder is missing. I created a default folder and changed the ownder and group to asterisk. I then tried creat a new user and it does not seem to populate the extension users in the default folder.

Anyone seen this? or have any idea how to fix it?

I am seeing this same issue in both Freepbx 2.5.1.2 and 2.5.2.2. Upto a point 2.5.1.2 worked great and stopped working at some point as when I tried to simulate the same thing on it I just found out it stopped working though it has both the folders but a new extension is not created in the default folder. I am running the same Voicemail Module 2.5.1.6 on both freepbx versions. So I am guessing it is a problem with 2.5.1.6 as I am sure I must have upgraded the module on my older Freepbx 2.5.1.2

I am running PIAF 1.4 64bit

Thanks,

Kim

kimkhan · September 13, 2009, 11:41am

I have just upgraded to 2.6.0.RC2.1 and tried creating an extension with voicemail and the user was not created under /var/spool/…/voicemail/default

A link was created in the /device folder.

Seems like a bug that is passed on from voicemail module 2.5.1.6

Thanks in advance for any help on this.

Kim

hosdes · September 16, 2009, 5:00pm

when you create an extension in freepbx, freepbx’s default is 111@device. In ssh, I go t /var/spool/asterisk/voicemail/device I see our extensions with symlink to /var/spool/asterisk/voicemail/default/111/. When I go to /default there is no extension directory. There was one which must be a default one. So I copied this one 1234 as 111 and tried this. Did not work.

Has anyone been able to solve this problem? Our freepbx is basically out of order. People want their voicemail.

hosdes · September 17, 2009, 3:45am

when I create a extension in freepbx 2.5.2.2 it creates a symlink in /var/spool/asterisk/voicemail/device but does not create a directory in /default

device ownership is www-data:www-data and default ownership is www-data:asterisk.

please advice.

pauls · September 29, 2009, 10:48pm

We had the same lock out problem with our mailboxes, removed them then re added them.

derschatten · October 2, 2009, 9:33am

Under voicemail setting on the phones make it ####@default so if you are ext 200 it would be 200@default.