[Home]

Summary:ASTERISK-17580: [patch] Voicemail doesn't read/delete messages in one case
Reporter:tootai (tootai)Labels:
Date Opened:2011-03-19 05:57:47Date Closed:2011-04-18 04:11:44
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail
Versions:1.4.40 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) bug18998.1.4.39.2.diff.txt
( 1) bug18998.diff.txt
( 2) bug18998.diff2.txt
( 3) bug18998-1.8.2.3.diff.txt
( 4) close_mailbox-1.4.39.2.c
Description:When listening the voicemailbox and new callers leave a new message something goes wrong: after the user has read and deleted all messages, the last one is not destroyed and the new incoming recorded messages are lost.

Below the relevant logs of an user reading his mailbox with 16 messages waiting (#<b></b>0 to #<b></b>15). During his reading, a new message was left while reading message #<b></b>5. All 16 messages where destroyed, voicemailbox should and has one message, number #<b></b>16. But when calling Voicemailmain, I get:

[2011-03-19 11:15:28] NOTICE[28981] app_voicemail.c: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/100/INBOX, expected 0 but found 1 message(s) in box with max threshold of 100.

app_voicemail.c:5917 play_message: No message attribute file?!! (/var/spool/asterisk/voicemail/default/100/INBOX/msg0000.txt)

dh@chacomx:/var/spool/asterisk/voicemail/default/100/INBOX$ ls -al
total 532
drwxr-xr-x 2 root root   4096 2011-03-19 11:15 .
drwxr-xr-x 8 root root   4096 2011-03-19 11:14 ..
-rwxr-xr-x 1 root root  45144 2011-03-18 22:00 msg0016.gsm
-rw-r--r-- 1 root root    264 2011-03-18 22:00 msg0016.txt
-rwxr-xr-x 1 root root 437804 2011-03-18 22:00 msg0016.wav
-rwxr-xr-x 1 root root  44520 2011-03-18 22:00 msg0016.WAV

So Asterisk is looking for msg0000 but found msg0016. There is no possibility to treat this message, only rename the file as msg0000.* give the possibility to listen and delete it.

****** ADDITIONAL INFORMATION ******

In 1.4.39 the problem was already existing. Didn't notice that in 1.4.28
Comments:By: Alec Davis (alecdavis) 2011-03-30 22:34:02

I believe the issue is in close_mailbox.

Currently experiencing the same when using ODBC storage.
https://reviewboard.asterisk.org/r/1153/
By: Alec Davis (alecdavis) 2011-03-31 05:32:14

uploaded bug18998.diff.txt

For 1.4 SVN-branch-1.4-r311203M, hopefully will apply to 1.4.40

In close_mailbox, re-evaluate number of messages as more may have arrived, before deleting and shuffling down a slot.
That way, no gaps are left in sequence.

Tested with file based storage.
Started with 6 messages, delete 2, and while this is happening quickly leave 4 more, then hangup from voicemail.

Achieved by dialing an extension that goes directly to voicemail then pressing '##' which avoids the prompts, and just says goodbye.
By: Alec Davis (alecdavis) 2011-03-31 05:43:07

Also tested deleting all 8 messages (0 - 7), and received 1 new message during this time.

asterix:/var/spool/asterisk/voicemail/default/820/INBOX# ls -latr *.txt
...
-rw-r--r-- 1 root root   252 Mar 31 23:22 msg0007.txt << Still with mailbox open
-rw-r--r-- 1 root root   252 Mar 31 23:36 msg0008.txt << this one arrived after opening mailbox

hangup from voicemail:

asterix:/var/spool/asterisk/voicemail/default/820/INBOX# ls -latr *.txt
-rw-r--r-- 1 root root   252 Mar 31 23:36 msg0000.txt <<after closing mailbox, now is 0 :)


Message left at 23:36, now is message 0.
By: tootai (tootai) 2011-03-31 06:00:16

Well, it's still not OK: if you receive one message during listening mailbox all is good. But 2 or more, same initial problem.msg0003 is the second I left.

root@peech:/var/spool/asterisk/voicemail/default/820/INBOX# ls -al
total 232
drwxr-xr-x 2 root root   4096 mar 31 12:53 .
drwxr-xr-x 8 root root   4096 sep 25  2010 ..
-rwxr-xr-x 1 root root  18480 mar 31 12:50 msg0003.gsm
-rw-r--r-- 1 root root    299 mar 31 12:50 msg0003.txt
-rwxr-xr-x 1 root root 179244 mar 31 12:50 msg0003.wav
-rwxr-xr-x 1 root root  18260 mar 31 12:50 msg0003.WAV
By: Alec Davis (alecdavis) 2011-03-31 06:18:51

On the console did you get.

[2011-04-01 00:13:13] NOTICE[6378]: app_voicemail.c:6070 close_mailbox: 2 messages arrived while mailbox was open

I just tried it again.
Open mailbox, you have 1 New message.
-rw------- 1 root root  1490 Apr  1 00:08 msg0000.WAV
-rw------- 1 root root 14124 Apr  1 00:08 msg0000.wav
-rw-r--r-- 1 root root   252 Apr  1 00:08 msg0000.txt
-rw------- 1 root root  1452 Apr  1 00:08 msg0000.gsm

Left 2 more messages.
-rwxr-xr-x 1 root root   125 Apr  1 00:12 msg0001.WAV
-rwxr-xr-x 1 root root   684 Apr  1 00:12 msg0001.wav
-rwxr-xr-x 1 root root    66 Apr  1 00:12 msg0001.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:12 msg0001.txt
-rwxr-xr-x 1 root root  3960 Apr  1 00:12 msg0002.WAV
-rwxr-xr-x 1 root root 38764 Apr  1 00:12 msg0002.wav
-rwxr-xr-x 1 root root  3993 Apr  1 00:12 msg0002.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:13 msg0002.txt

Pressed 7 to delete my only message, hangup.

-rwxr-xr-x 1 root root   125 Apr  1 00:12 msg0000.WAV
-rwxr-xr-x 1 root root   684 Apr  1 00:12 msg0000.wav
-rwxr-xr-x 1 root root    66 Apr  1 00:12 msg0000.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:12 msg0000.txt
-rwxr-xr-x 1 root root  3960 Apr  1 00:12 msg0001.WAV
-rwxr-xr-x 1 root root 38764 Apr  1 00:12 msg0001.wav
-rwxr-xr-x 1 root root  3993 Apr  1 00:12 msg0001.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:13 msg0001.txt

There may be a difference between the 1.4 SVN branch and 1.4.40, I'm testing with 1.4 SVN branch downloaded an hour or so ago.


By: Alec Davis (alecdavis) 2011-03-31 06:41:19

I think the resequencing in 1.4.40 for open_mailbox has changed in 1.4 SVN, as I don't get

2011-03-19 11:15:28] NOTICE[28981] app_voicemail.c: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/100/INBOX, expected 0 but found 1 message(s) in box with max threshold of 100

--------------------

After puposely deleting msg0000.* and leaving just msg0001.* as below
-rwxr-xr-x 1 root root  3960 Apr  1 00:12 msg0001.WAV
-rwxr-xr-x 1 root root 38764 Apr  1 00:12 msg0001.wav
-rwxr-xr-x 1 root root  3993 Apr  1 00:12 msg0001.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:13 msg0001.txt

As I open the mailbox to listen to new messages I get:
[2011-04-01 00:33:18] NOTICE[18239]: app_voicemail.c:6042 open_mailbox: Resequencing Mailbox: /var/spool/asterisk/voicemail/default/820/INBOX, expected 2 but found 1 message(s) in box with max threshold of 100.

-rwxr-xr-x 1 root root  3960 Apr  1 00:12 msg0000.WAV
-rwxr-xr-x 1 root root 38764 Apr  1 00:12 msg0000.wav
-rwxr-xr-x 1 root root  3993 Apr  1 00:12 msg0000.gsm
-rw-r--r-- 1 root root   252 Apr  1 00:13 msg0000.txt

I can then listen to the 1 New message.
By: Alec Davis (alecdavis) 2011-03-31 07:10:30

tootai:
I can confirm 1.4.40 doesn't resequence properly when opening the mailbox, and message sequence is corrupt.

last_message_index has been reworked since 1.4.40.
By: Digium Subversion (svnbot) 2011-04-01 01:47:00

Repository: asterisk
Revision: 312070

U   branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r312070 | alecdavis | 2011-04-01 01:46:56 -0500 (Fri, 01 Apr 2011) | 16 lines

app_voicemail: close_mailbox needs to respect additional messages while mailbox is open.

close_mailbox leave gaps in message sequence if messages are deleted and new messages
arrive during this time, this is because the shuffle down to slot 0, only shuffles
the number of pre-existing messages when mailbox is opened, ignoring new arrivals.

Fix: in close_mailbox re-evaluate number of messages before the shuffle, this then includes new arrivals.

Happens on filebased or ODBC storage.

(issues ASTERISK-17613,ASTERISK-17207,ASTERISK-17299,ASTERISK-17580)
Reported by: alecdavis,tootai,afosorio

Review: https://reviewboard.asterisk.org/r/1153/


------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=312070
By: Digium Subversion (svnbot) 2011-04-01 02:25:58

Repository: asterisk
Revision: 312103

_U  branches/1.6.2/
U   branches/1.6.2/apps/app_voicemail.c

------------------------------------------------------------------------
r312103 | alecdavis | 2011-04-01 02:25:55 -0500 (Fri, 01 Apr 2011) | 22 lines

Merged revisions 312070 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r312070 | alecdavis | 2011-04-01 19:46:56 +1300 (Fri, 01 Apr 2011) | 16 lines
 
 app_voicemail: close_mailbox needs to respect additional messages while mailbox is open.
 
 close_mailbox leave gaps in message sequence if messages are deleted and new messages
 arrive during this time, this is because the shuffle down to slot 0, only shuffles
 the number of pre-existing messages when mailbox is opened, ignoring new arrivals.
 
 Fix: in close_mailbox re-evaluate number of messages before the shuffle, this then includes new arrivals.
 
 Happens on filebased or ODBC storage.
 
 (issues ASTERISK-17613,ASTERISK-17207,ASTERISK-17299,ASTERISK-17580)
 Reported by: alecdavis,tootai,afosorio
 
 Review: https://reviewboard.asterisk.org/r/1153/
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=312103
By: Digium Subversion (svnbot) 2011-04-01 02:32:16

Repository: asterisk
Revision: 312117

_U  branches/1.8/
U   branches/1.8/apps/app_voicemail.c

------------------------------------------------------------------------
r312117 | alecdavis | 2011-04-01 02:32:13 -0500 (Fri, 01 Apr 2011) | 29 lines

Merged revisions 312103 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

................
 r312103 | alecdavis | 2011-04-01 20:25:54 +1300 (Fri, 01 Apr 2011) | 22 lines
 
 Merged revisions 312070 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r312070 | alecdavis | 2011-04-01 19:46:56 +1300 (Fri, 01 Apr 2011) | 16 lines
   
   app_voicemail: close_mailbox needs to respect additional messages while mailbox is open.
   
   close_mailbox leave gaps in message sequence if messages are deleted and new messages
   arrive during this time, this is because the shuffle down to slot 0, only shuffles
   the number of pre-existing messages when mailbox is opened, ignoring new arrivals.
   
   Fix: in close_mailbox re-evaluate number of messages before the shuffle, this then includes new arrivals.
   
   Happens on filebased or ODBC storage.
   
   (issues ASTERISK-17613,ASTERISK-17207,ASTERISK-17299,ASTERISK-17580)
   Reported by: alecdavis,tootai,afosorio
   
   Review: https://reviewboard.asterisk.org/r/1153/
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=312117
By: Digium Subversion (svnbot) 2011-04-01 02:43:05

Repository: asterisk
Revision: 312118

_U  trunk/
U   trunk/apps/app_voicemail.c

------------------------------------------------------------------------
r312118 | alecdavis | 2011-04-01 02:43:00 -0500 (Fri, 01 Apr 2011) | 36 lines

Merged revisions 312117 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r312117 | alecdavis | 2011-04-01 20:32:12 +1300 (Fri, 01 Apr 2011) | 29 lines
 
 Merged revisions 312103 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r312103 | alecdavis | 2011-04-01 20:25:54 +1300 (Fri, 01 Apr 2011) | 22 lines
   
   Merged revisions 312070 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r312070 | alecdavis | 2011-04-01 19:46:56 +1300 (Fri, 01 Apr 2011) | 16 lines
     
     app_voicemail: close_mailbox needs to respect additional messages while mailbox is open.
     
     close_mailbox leave gaps in message sequence if messages are deleted and new messages
     arrive during this time, this is because the shuffle down to slot 0, only shuffles
     the number of pre-existing messages when mailbox is opened, ignoring new arrivals.
     
     Fix: in close_mailbox re-evaluate number of messages before the shuffle, this then includes new arrivals.
     
     Happens on filebased or ODBC storage.
     
     (issues ASTERISK-17613,ASTERISK-17207,ASTERISK-17299,ASTERISK-17580)
     Reported by: alecdavis,tootai,afosorio
     
     Review: https://reviewboard.asterisk.org/r/1153/
   ........
 ................
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=312118
By: Alec Davis (alecdavis) 2011-04-01 05:52:24

tootai:

After all these patches, there still is an issue with 1.4 SVN

Assuming msg0000 was missing, but msg0001 - msg0004 exist.
The next new message should be msg0005, but when leaving a new message, it would still try msg0000 first, even if msg00004 was there.

bug18998.diff2.txt fixes the above, it's the same method as is used for 1.6.2 up to trunk
By: Digium Subversion (svnbot) 2011-04-01 06:02:28

Repository: asterisk
Revision: 312290

U   branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r312290 | alecdavis | 2011-04-01 06:02:27 -0500 (Fri, 01 Apr 2011) | 13 lines

app_voicemail: leave_vociemail doesn't use last_message_index to store next message

trivial change to bring inline with 1.6.2 1.8 and trunk.
The symptom was if msg0000 was missing, and the last was msg0004,
the next msgnum would be msg0000 when it should have been msg0005  

(issue ASTERISK-17580)
Reported by: tootai
Patches:
     bug18998.diff2.txt uploaded by alecdavis (license 585)
Tested by: alecdavis


------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=312290
By: tootai (tootai) 2011-04-01 08:18:30

As I see, you modified the app_voicemail.c for all versions including trunk. But for patching a running Asterisk -here 1.4.39-2-, they are only 2 patches. What is missing is

Repository: asterisk
Revision: 312070

U branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r312070 | alecdavis | 2011-04-01 01:46:56 -0500 (Fri, 01 Apr 2011) | 16 lines

Am I right?

--
Daniel
By: Alec Davis (alecdavis) 2011-04-01 19:08:09

bug18998.1.4.39.2.diff.txt includes all related patches that I commited last night.

basically it's a diff between app_voicemail from 1.4.39.2 and 1.4 svn, then prune out the forward transfer and others.

tested on 1.4.39.2
1). open_mailbox sucessfully resequences
2). close_mailbox doesn't leave marooned messages, after messages arrive while mailbox is open, and messages are deleted by user.
3). leaving a message when any message msgXXXX in the sequence is missing now correctly used the highest msgnum +1


By: Alec Davis (alecdavis) 2011-04-02 03:37:07

bug18998-1.8.2.3.diff.txt is for 1.8.2.3 which includes all patches relevant patches to app_voicemail

This has been tested on our own 1.8.2.3 production server, with ODBC storage, with existing corrupt maillboxes, in addition to the tests in ~133301

Also tested on a 1.8.2.3 test server, using file based storage.
By: tootai (tootai) 2011-04-02 07:33:34

I try to apply the bug18998.1.4.39.2.diff.txt and get an error on applying HUNK ASTERISK-7. I remove the part (it's the last one starting at line 6020) and apply it manually. During the make I have:


  [CC] app_voicemail.c -> app_voicemail.o
app_voicemail.c: In function ‘close_mailbox’:
app_voicemail.c:6101: error: ‘last_msg_index’ undeclared (first use in this function)
app_voicemail.c:6101: error: (Each undeclared identifier is reported only once
app_voicemail.c:6101: error: for each function it appears in.)
make[1]: *** [app_voicemail.o] Erreur 1
make: *** [apps] Erreur 2

--
Daniel
By: Alec Davis (alecdavis) 2011-04-02 15:32:46

Looks like the declaration for 'last_msg_index' got missed some how, although it's in the diff????

The beginning of close_mailbox should look like this:<pre>
static int close_mailbox(struct vm_state *vms, struct ast_vm_user *vmu)
{
       int x = 0;
#ifndef IMAP_STORAGE
       int last_msg_index;    <<<<<<< Here is the missing line
       int res = 0, nummsg;
#endif
</pre>


By: Alec Davis (alecdavis) 2011-04-02 15:49:02

The bit below from the diff, changes close_mailbox, it is required.
This code prevents the gaps in the message sequence that occur when new messages arrive while the user has same mailbox open, and the user deletes some messages.<pre>
@@ -6020,9 +6097,14 @@
       /* Get the deleted messages fixed */
       if (vm_lock_path(vms->curdir))
               return ERROR_LOCK_PATH;
-
+
+       last_msg_index = last_message_index(vmu, vms->curdir);
+       if (last_msg_index !=  vms->lastmsg) {
+               ast_log(LOG_NOTICE, "%d messages arrived while mailbox was open\n", last_msg_index - vms->lastmsg);
+       }
+
       /* must check up to last detected message, just in case it is erroneously greater than maxmsg */
-       for (x = 0; x < vms->lastmsg + 1; x++) {
+       for (x = 0; x < last_msg_index + 1; x++) {
               if (!vms->deleted[x] && (strcasecmp(vms->curbox, "INBOX") || !vms->heard[x])) {
                       /* Save this message.  It's not in INBOX or hasn't been heard */
                       make_file(vms->fn, sizeof(vms->fn), vms->curdir, x);
</pre>
By: Alec Davis (alecdavis) 2011-04-02 16:47:45

tootai:
close_mailbox-1.4.39.2.c is what close_mailbox should look like after patching.

In guessing bug18998.1.4.39.2.diff.txt patch failed to apply due to previous patch attempts, I'm not sure.

Is your 1.4.39.2 an svn checkout or a tarball download?
By: tootai (tootai) 2011-04-03 05:22:01

Tarball. Will take a app_voicemail.c from 1.4.39.1, apply the patch and see what happends.

--
Daniel
By: tootai (tootai) 2011-04-03 05:32:17

Applied on a stock 1.4.39 and went fine. Will test tomorrow.

Thanks for your support
By: Alec Davis (alecdavis) 2011-04-04 00:00:12

I created the 1.4.39.2 patch using the 1.4.39.2 tag release using
svn co http:/<b></b>/svn.digium.com/svn/asterisk/tags/1.4.39.2/ asterisk-1.4.39.2

Today downloaded the 1.4.39.2 tarball to check my sanity from
http://downloads.asterisk.org/pub/telephony/asterisk/old-releases/asterisk-1.4.39.2.tar.gz and applied the same bug18998.1.4.39.2.diff.txt patch.

It applied clean, and complied successfully.


By: Alec Davis (alecdavis) 2011-04-18 04:11:44

Fixed all branches 1.4 - 1.6.2 - 1.8 and trunk.