[Home]

Summary:ASTERISK-17118: [patch] Voicemail files out of sequence
Reporter:Michael Gaudette (bluefox)Labels:
Date Opened:2010-12-16 09:50:50.000-0600Date Closed:2011-01-25 11:06:00.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) bug18486.patch
Description:I get this regularly for some mailboxes. Can't find what they do different than others, but it's always the same people.  I have no third-party voicemail tools that is removing voicemails or anything else.

CLI message:
[Dec 16 10:45:43] NOTICE[5587]: app_voicemail.c:7432 open_mailbox: Mailbox: /var/spool/asterisk/voicemail/xxxx/yyyy/INBOX, expected 0 but found 3 message(s) in box with max threshold of 100.

In the folder, I find that messages are out of sequence.  Most times msg000 is missing but msg0001 is there.  Other times msg0000 is there but (let's say) msg0004 is missing so there is msg0001, 2, 3, 5 and 6.




****** STEPS TO REPRODUCE ******

I wish I knew

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

It didn't happen on the release version 1.6.2.15, but I had to use 1.6.2.15-SVN for some reason and it did happen then.

I know there was mention of changes in the voicemail code in this version, so that likely broke it.
Comments:By: Jeff Peeler (jpeeler) 2011-01-05 14:52:37.000-0600

Here is a 1.6.2 version of the patch, please test. You said on the other issue that you were running 1.6.2.16-rc1 and probably just updating app_voicemail from SVN will be fine.
By: Michael Gaudette (bluefox) 2011-01-10 08:48:15.000-0600

I tried the patch last Thursday.  As of now it hasn't happened again, but there was not much activity (week-end after Chrismtas).  I will wait 2-3 days but if it hasn't happened by then I would say it's fixed.
By: Michael Gaudette (bluefox) 2011-01-10 08:49:35.000-0600

I see this:
[Jan 10 09:43:50] NOTICE[2034]: app_voicemail.c:7470 open_mailbox: Resequencing mailbox: /var/spool/asterisk/voicemail/CONTEXT/MAILBOX/INBOX, expected 5 but found 3 message(s) in box with max threshold of 100.

I imagine that means the patch corrects the problem?
By: Michael Gaudette (bluefox) 2011-01-10 08:49:36.000-0600

I see this:
[Jan 10 09:43:50] NOTICE[2034]: app_voicemail.c:7470 open_mailbox: Resequencing mailbox: /var/spool/asterisk/voicemail/CONTEXT/MAILBOX/INBOX, expected 5 but found 3 message(s) in box with max threshold of 100.

I imagine that means the patch corrects the problem?
By: Jeff Peeler (jpeeler) 2011-01-10 08:57:44.000-0600

That means the patch has attempted to correct the problem. You need to manually check in /var/spool/asterisk/voicemail/CONTEXT/MAILBOX/INBOX and make sure the files are in order and none are missing. If that's the case, then everything is fixed.
By: Michael Gaudette (bluefox) 2011-01-10 13:47:34.000-0600

Apparently I can't transfer messages anymore.  When attempting to transfer from 705 to 701 (two existing mailboxes in the same context) the original message was deleted but nowhere in 701 was the message found.

There were no CLI messages.
By: Jeff Peeler (jpeeler) 2011-01-12 13:50:15.000-0600

I assume you mean you forwarded the message and that it is only broken with the patch? I'm observing it to be working with the patch. Can you elaborate on the steps to reproduce this problem?
By: Michael Gaudette (bluefox) 2011-01-13 09:40:22.000-0600

I tried again, same thing.  I simply forwarded the message from  mailbox 705 to 702 by pressing 8 at the end of the message, choosing 702, hearing the 702 mailbox name, then pressing 2 (forward as is).  Message was erased, but isn't found in 702/INBOX.

This was not reported prior to the patch, but since the patch a customer reported it and I can't get it working myself.

I get this now in the CLI, verbose 3:
[Jan 13 10:39:07] NOTICE[13723]: app_voicemail.c:4996 copy_message: Copying message from 705@context to 702@context
[Jan 13 10:39:07] WARNING[13723]: app_voicemail.c:4553 add_email_attachment: Sox failed to re-encode /var/spool/asterisk/voicemail/context/702/INBOX/msg0000.WAV: An error occurred during file processing (have you installed support for all sox file formats?)
[Jan 13 10:39:07] WARNING[13723]: app_voicemail.c:4555 add_email_attachment: Voicemail attachment will have no volume gain.
[Jan 13 10:39:07] WARNING[13723]: app_voicemail.c:4019 base_encode: Failed to open file: /var/spool/asterisk/voicemail/context/702/INBOX/msg0000.WAV: No such file or directory
By: Michael Gaudette (bluefox) 2011-01-13 09:41:01.000-0600

FYI, the message are forwarded to email though (they are set as send by email but do not delete).
By: Jeff Peeler (jpeeler) 2011-01-14 11:56:27.000-0600

Can you test without the patch then? I'm not sure how the patch would affect that issue.
By: Michael Gaudette (bluefox) 2011-01-18 08:48:30.000-0600

I will try, but I can reproduce this 100% when forwarding a message from one mailbox to another

I use format=wav49|gsm|wav in voicemail.conf, and it works when receiving the original message or sending toe mail.
By: Michael Gaudette (bluefox) 2011-01-18 09:16:21.000-0600

It will be difficult quickly to use the system without the patch (restarting it is a no-no right now) but an identical setup with 1.6.2.13 (and Centos 32 bits instead of 64, the only significant different as far as I can tell) works fine with transferring voicemails.
By: Michael Gaudette (bluefox) 2011-01-19 09:25:22.000-0600

In an effort to help me troubleshoot this and actually try to modify the code myself, could you tell me whether reloading module app_voicemail  in the CLI would allow me to change the code in app_voicemail.c (to leave debug traces) without restarting entirely asterisk?
By: fordattenborough (fordattenborough) 2011-01-19 11:34:07.000-0600

I'm seeing the same voicemail sequencing issue in 1.8.2 running on Centos.  Manually renaming the files to restart the numbering sequence at 0 temporarily resolves the issue.

[Jan 19 10:31:36] NOTICE[4483]: app_voicemail.c:7727 open_mailbox: Mailbox: /var/spool/asterisk/voicemail/redacted/149/Old, expected 2 but found 4 message(s) in box with max threshold of 100.
By: Michael Gaudette (bluefox) 2011-01-19 23:41:16.000-0600

Found the issue!!!

In the function copy_message() of app_voicemail.c (the one for file storage, not IMAP, around line 4989) you call vm_delete(topath) while it should be vm_delete(frompath).  You gotta delete the old message, not the one that was just put in the new mailbox.

I tested it, it seems to work seem.  the sox problem was related to this,but is gone now. (was trying to convert a non-existent file I guess).

Am I correct?
By: Sébastien Couture (sysreq) 2011-01-20 01:27:13.000-0600

bluefox: That kind of makes sense.. I've had lots of problems with sox failing to re-encode files in the past months too; I'll surely test this on at least a server. Thanks for the heads up!
By: fordattenborough (fordattenborough) 2011-01-20 01:53:56.000-0600

Well, I've been watching a voicemail INBOX directory where I had three sets of voicemail files...msg0000.txt and .WAV, msg0001.txt and .WAV and msg0002.txt and .WAV.  These were manually resequenced by me earlier in the day.

After the user attempted to listen to these I had the following log entry.

[Jan 19 17:22:24] NOTICE[7970] app_voicemail.c: Mailbox: /var/spool/asterisk/voicemail/redacted/150/INBOX, expected 2 but found 5 message(s) in box with max threshold of 100.
[Jan 19 17:22:24] NOTICE[7970] app_voicemail.c: Mailbox: /var/spool/asterisk/voicemail/redacted/150/INBOX, expected 2 but found 5 message(s) in box with max threshold of 100.
[Jan 19 17:23:16] WARNING[7970] app_voicemail.c: No message attribute file?!! (/var/spool/asterisk/voicemail/redacted/150/INBOX/msg0002.txt)

Now in 150's directory I have:

msg0004.txt  msg0004.WAV  msg0005.txt  msg0005.WAV  msg0006.txt  msg0006.WAV

Hope this helps.
By: Jeff Peeler (jpeeler) 2011-01-20 13:17:28.000-0600

Am I correct in that bluefox found the issue was not related to my patch? And I assume cwolff09 you are demonstrating the current issue without the patch applied?
By: Michael Gaudette (bluefox) 2011-01-20 13:20:02.000-0600

I don't know, I assume the issue did not occur prior to the patch. (I would have heard of it since this function is used a lot).

What was happening prior to the patch, I think (pure educated conjecture), is the destination mailbox getting its email deleted and then being out of sequence and unusable. Now the destination mailbox is still usable but the email is still deleted.
By: fordattenborough (fordattenborough) 2011-01-20 13:22:45.000-0600

Jpeeler: I am demonstrating the issue prior to patching...as I wasn't certain whether the patch could be applied to 1.8.2.  Thank you.
By: Jeff Peeler (jpeeler) 2011-01-20 15:15:28.000-0600

bluefox: the only way the code you are mentioning will get executed is if the existence for the message you are forwarding does not exist. I have no idea what you are experiencing, but if others say the patch is good I'm going to have to ask you to file a separate more detailed bug report.
By: Jeremiah Millay (jmillay) 2011-01-21 14:40:42.000-0600

I am able to repeat this issue when a I go to check new messages and then press 9 to save the message and choose 0 to save it to new messages (which puts it in INBOX again). Changes the file names from 0000 to 0001 assuming there is only one message in the folder.

I was running 1.6.2.9 and upgrade to 1.6.2.16 introduced this problem.

Not sure if any of this helps.
By: Jeff Peeler (jpeeler) 2011-01-21 15:18:30.000-0600

jmillay: and in that case, one you exit and return the files are renumbered back to 0000 correct? I'm assuming that of course you're testing the patch.
By: fordattenborough (fordattenborough) 2011-01-21 15:24:08.000-0600

@jmillay,

This is consistent with what I'm seeing.  The two problem users resave the voicemails as new messages which triggers the problem.

I haven't tried the patch yet as I don't have a confirmation that it should not introduce issues with 1.8.2.
By: Jeremiah Millay (jmillay) 2011-01-21 15:24:26.000-0600

No they are not renumbered back to 0000 on exit. I did not test the patch. I tested this with the current stable version 1.6.2.16.1. I am always able to reproduce this behavior. I get a log message similar to the ones other users have reported (....expected 0, found 1) and I am unable to access the messages after they have been saved.

I have seen this occur with messages in other folders as well. I think it happens when saving a message to the same folder it is being read from.

I will test the patch and get back to you as to if it corrects this behavior.
By: Digium Subversion (svnbot) 2011-01-25 10:58:33.000-0600

Repository: asterisk
Revision: 303676

U   branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r303676 | jpeeler | 2011-01-25 10:58:30 -0600 (Tue, 25 Jan 2011) | 20 lines

Fix voicemail sequencing for file based storage.

A previous change was made to account for when the number of voicemail messages
exceeds the max limit to be handled properly, but it caused gaps in the messages
to not be properly handled. This has now been resolved.

In later non 1.4 branches, it appears that resequencing wasn't even occurring
due from what appears and accidental code removal.

(closes issue ASTERISK-17130)
Reported by: JJCinAZ
Patches:
     bug18498v2.patch uploaded by jpeeler (license 325)

(closes issue ASTERISK-17118)
Reported by: bluefox
Patches:
     bug18486.patch uploaded by jpeeler (license 325)


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

http://svn.digium.com/view/asterisk?view=rev&revision=303676
By: Digium Subversion (svnbot) 2011-01-25 10:59:30.000-0600

Repository: asterisk
Revision: 303677

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

------------------------------------------------------------------------
r303677 | jpeeler | 2011-01-25 10:59:28 -0600 (Tue, 25 Jan 2011) | 26 lines

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

........
 r303676 | jpeeler | 2011-01-25 10:58:29 -0600 (Tue, 25 Jan 2011) | 20 lines
 
 Fix voicemail sequencing for file based storage.
 
 A previous change was made to account for when the number of voicemail messages
 exceeds the max limit to be handled properly, but it caused gaps in the messages
 to not be properly handled. This has now been resolved.
 
 In later non 1.4 branches, it appears that resequencing wasn't even occurring
 due from what appears and accidental code removal.
 
 (closes issue ASTERISK-17130)
 Reported by: JJCinAZ
 Patches:
       bug18498v2.patch uploaded by jpeeler (license 325)
 
 (closes issue ASTERISK-17118)
 Reported by: bluefox
 Patches:
       bug18486.patch uploaded by jpeeler (license 325)
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=303677
By: Digium Subversion (svnbot) 2011-01-25 11:02:40.000-0600

Repository: asterisk
Revision: 303678

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

------------------------------------------------------------------------
r303678 | jpeeler | 2011-01-25 11:02:39 -0600 (Tue, 25 Jan 2011) | 33 lines

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

................
 r303677 | jpeeler | 2011-01-25 10:59:28 -0600 (Tue, 25 Jan 2011) | 26 lines
 
 Merged revisions 303676 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r303676 | jpeeler | 2011-01-25 10:58:29 -0600 (Tue, 25 Jan 2011) | 20 lines
   
   Fix voicemail sequencing for file based storage.
   
   A previous change was made to account for when the number of voicemail messages
   exceeds the max limit to be handled properly, but it caused gaps in the messages
   to not be properly handled. This has now been resolved.
   
   In later non 1.4 branches, it appears that resequencing wasn't even occurring
   due from what appears and accidental code removal.
   
   (closes issue ASTERISK-17130)
   Reported by: JJCinAZ
   Patches:
         bug18498v2.patch uploaded by jpeeler (license 325)
   
   (closes issue ASTERISK-17118)
   Reported by: bluefox
   Patches:
         bug18486.patch uploaded by jpeeler (license 325)
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=303678
By: Digium Subversion (svnbot) 2011-01-25 11:05:59.000-0600

Repository: asterisk
Revision: 303679

_U  trunk/
U   trunk/apps/app_voicemail.c

------------------------------------------------------------------------
r303679 | jpeeler | 2011-01-25 11:05:57 -0600 (Tue, 25 Jan 2011) | 40 lines

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

................
 r303678 | jpeeler | 2011-01-25 11:02:38 -0600 (Tue, 25 Jan 2011) | 33 lines
 
 Merged revisions 303677 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r303677 | jpeeler | 2011-01-25 10:59:28 -0600 (Tue, 25 Jan 2011) | 26 lines
   
   Merged revisions 303676 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r303676 | jpeeler | 2011-01-25 10:58:29 -0600 (Tue, 25 Jan 2011) | 20 lines
     
     Fix voicemail sequencing for file based storage.
     
     A previous change was made to account for when the number of voicemail messages
     exceeds the max limit to be handled properly, but it caused gaps in the messages
     to not be properly handled. This has now been resolved.
     
     In later non 1.4 branches, it appears that resequencing wasn't even occurring
     due from what appears and accidental code removal.
     
     (closes issue ASTERISK-17130)
     Reported by: JJCinAZ
     Patches:
           bug18498v2.patch uploaded by jpeeler (license 325)
     
     (closes issue ASTERISK-17118)
     Reported by: bluefox
     Patches:
           bug18486.patch uploaded by jpeeler (license 325)
   ........
 ................
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=303679