ASTERISK-15240: [patch] Deleting Multiple IMAP voicemails does not work reliably

[Home]

Summary: ASTERISK-15240: [patch] Deleting Multiple IMAP voicemails does not work reliably

Reporter: Noah Miller (noahisaac) Labels:

Date Opened: 2009-11-30 10:56:08.000-0600 Date Closed: 2010-07-20 17:43:51

Priority: Minor Regression? No

Status: Closed/Complete Components: Applications/app_voicemail/IMAP

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) 20100623__issue16350.diff.txt

Description: Deleting a single IMAP voicemail in one VoicemailMain() session always works as expected. When deleting two or more IMAP messages in a single VoicemailMain() session, the results are unpredictable: some or all of the messages do not get deleted. The more messages that are deleted, the more likely it is to get the error. If five or more messages are deleted, the error will always happen, and some of the messages that are supposed to be deleted will not be deleted.

When the VoicemailMain() session ends, this message is displayed in the CLI:
[Nov 30 10:54:34] ERROR[6887]: app_voicemail.c:2359 mm_log: IMAP Error: IMAP protocol error: Error in IMAP command STORE: Invalid messageset
[Nov 30 10:54:34] ERROR[6887]: app_voicemail.c:2359 mm_log: IMAP Error: Error in IMAP command STORE: Invalid messageset

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

IMAP Server: Dovecot 1.2.8
IMAP Client: imap-2007e

This system had previously been running a version of 1.6.0-svn (after 1.6.0.9), and probably an older version of dovecot (though the same version of the UW-IMAP client). I don't think this issue showed up under that setup.

Comments: By: Noah Miller (noahisaac) 2010-03-11 22:06:19.000-0600

Just want to add that this issue still exists in 1.6.2.5 (and dovecot version 1.2.10). I know very little about UW c-client -- Does anybody have any suggestions about how I might troubleshoot this? I guess I'll do some testing with different IMAP software.
By: Noah Miller (noahisaac) 2010-03-11 22:56:15.000-0600

Just tried with a uw-imap server, same result.
By: Noah Miller (noahisaac) 2010-03-11 23:05:50.000-0600

Scratch that, the other server I tried is also dovecot.
By: Noah Miller (noahisaac) 2010-03-12 00:12:14.000-0600

Issue also exists on Courier IMAP, though interestingly, the cli warning/error is different. Under Courier, I get:

WARNING[22891]: app_voicemail.c:2358 mm_log: IMAP Warning: Invalid message sequence number: 5
By: Noah Miller (noahisaac) 2010-03-13 22:44:40.000-0600

This issue does NOT exist in Asterisk 1.6.1.6. I'm looking through the IMAP changes between 1.6.1.6 and 1.6.1.10 to see which one is the culprit.
By: Noah Miller (noahisaac) 2010-04-13 13:17:25

I'm at a little bit of a loss here. The only appreciable difference in vm_imap_delete() between 1.6.1.6 and 1.6.1.10 is that an explicit expunge was ADDED in 1.6.1.10. Of course, when I tried removing it, no voicemails are deleted at all. So a couple of questions:

1. How were IMAP voicemails actually deleted in 1.6.1.6?

2. Can anyone think of any changes to app_voicemail.c that would cause IMAP voicemails to not get deleted?
By: SplatNIX (uxbod) 2010-05-07 07:30:43

I am also seeing this on 1.6.1.14 when connected to a Zimbra 6.0.6 IMAP server. Is there any way I can help with debugging ?
By: SplatNIX (uxbod) 2010-05-07 08:00:11

Have just tested using 1.6.1.14. Left six voicemails and all were delivered successfully to the IMAP server. Connected back to Comedian mail and deleted everyone. Disconnected and on checking the Inbox only three had been expunged and the Asterisk console reported:

[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: IMAP protocol error: parse error: invalid message sequence number: 172
[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: parse error: invalid message sequence number: 172
[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: IMAP protocol error: parse error: invalid message sequence number: 173
[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: parse error: invalid message sequence number: 173
[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: IMAP protocol error: parse error: invalid message sequence number: 174
[May 7 08:56:56] ERROR[18459]: app_voicemail.c:2367 mm_log: IMAP Error: parse error: invalid message sequence number: 174
By: SplatNIX (uxbod) 2010-05-07 08:23:51

Have tested on a 1.6.2.6 system and get exactly the same result.
By: Noah Miller (noahisaac) 2010-05-07 08:58:31

Since I don't even know where to start with gdb on this one, I'm thinking of just doing the brute-force method: start with 1.6.1.6, and apply all app_voicemail.c changes that happened after that release and test IMAP deleting after each one. A bit painful, but it should do the trick.
By: SplatNIX (uxbod) 2010-05-07 09:03:29

I believe there is a real link between this issue and http://issues.asterisk.org/view.php?id=17306. On the other issue I left two voicemails, they appeared in the IMAP folder as VM-1 and VM-3. I then connected to Comedian and deleted both of them. On checking the IMAP folder VM-3 remained.
By: Leif Madsen (lmadsen) 2010-05-07 11:47:03

I think the resolution of ASTERISK-16069 would resolve this issue actually based on the testing by uxbod.
By: SplatNIX (uxbod) 2010-05-08 12:54:11

May I ask how these are marked as Minor when they can be perceived as a key feature for storage ?
By: Leif Madsen (lmadsen) 2010-05-10 11:30:36

Minor means the potential number of people affected by this issue, not the severity of the problem in your environment.
By: SplatNIX (uxbod) 2010-05-10 14:02:09

ASTERISK-16069 has been heavily updated with debug information.
By: SplatNIX (uxbod) 2010-05-12 04:00:28

The sequence numbering issue in 0017306 appears to have been fixed; though on testing a 1.6.1.14 system I still get the issue with deleting multiple VMs. I believe it may be down to how you exit Comedian Mail (CM). I left two VMs, then connected back in and pressed 1 to play, then 7, and when the second VM started I pressed 7 and then #. I got the EXPUNGE error and when connecting back into CM the second message was in the old folder. Playing and deleting it did remove it from the IMAP side as-well though.
By: Elazar Broad (ebroad) 2010-05-13 11:44:53

What happens if you move ast_mutex_lock(&vms->lock) in vp_imap_delete() right before:

/* find real message number based on msgnum */
/* this may be an index into vms->msgArray based on the msgnum. */
messageNum = vms->msgArray[msgnum];
By: SplatNIX (uxbod) 2010-05-13 12:06:44

Code is different in 1.6.2.X:

/* find real message number based on msgnum */
/* this may be an index into vms->msgArray based on the msgnum. */
messageNum = vms->msgArray[msgnum];
if (messageNum == 0) {
ast_log(LOG_WARNING, "msgnum %d, mailbox message %lu is zero.\n",msgnum,messageNum);
return;
}
if (option_debug > 2)
ast_log(LOG_DEBUG, "deleting msgnum %d, which is mailbox message %lu\n",msgnum,messageNum);
/* delete message */
snprintf (arg, sizeof(arg), "%lu",messageNum);
ast_mutex_lock(&vms->lock);
mail_setflag (vms->mailstream,arg,"\\DELETED");
mail_expunge(vms->mailstream);
ast_mutex_unlock(&vms->lock);
By: Elazar Broad (ebroad) 2010-05-13 12:22:45

Looks the same as in SVN trunk, what happens if we do this:
ast_mutex_lock(&vms->lock);
/* find real message number based on msgnum */
/* this may be an index into vms->msgArray based on the msgnum. */
messageNum = vms->msgArray[msgnum];
if (messageNum == 0) {
ast_log(LOG_WARNING, "msgnum %d, mailbox message %lu is zero.\n",msgnum,messageNum);
return;
}
if (option_debug > 2)
ast_log(LOG_DEBUG, "deleting msgnum %d, which is mailbox message %lu\n",msgnum,messageNum);
/* delete message */
snprintf (arg, sizeof(arg), "%lu",messageNum);

mail_setflag (vms->mailstream,arg,"\\DELETED");
mail_expunge(vms->mailstream);
ast_mutex_unlock(&vms->lock);
By: Elazar Broad (ebroad) 2010-05-17 14:48:54

Per uxbod's earlier comment, I don't believe that this issue is related to the message sequencing issue that have been recently fixed in SVN. While I am not completely sure what the issue is, I have a feeling that it is a concurrency issue with the way vms->msgArray[msgnum] is accessed.

elazar
By: Tilghman Lesher (tilghman) 2010-06-03 10:11:18

I wonder if this might be fixed if we reverse the order in which voicemails are deleted. My theory is that IMAP renumbers the indexes immediately when one is deleted, so supposing that you had 5 voicemails and you chose to delete
2, 3, and 4, the current sequence is:
1 2 3 4 5
delete second
1 3 4 5
delete third
1 3 5
delete fourth (3 messages, invalid index number).

If we delete in reverse:
1 2 3 4 5
delete fourth
1 2 3 5
delete third
1 2 5
delete second
1 5
By: Tilghman Lesher (tilghman) 2010-06-23 13:19:25

Well, here's a patch to test that theory.
By: Leif Madsen (lmadsen) 2010-07-06 10:22:36

Can some of the people experiencing this issue please test and report back on the patch supplied by Tilghman? Thanks!
By: Digium Subversion (svnbot) 2010-07-20 17:23:12

Repository: asterisk
Revision: 278261

U branches/1.4/apps/app_voicemail.c

------------------------------------------------------------------------
r278261 | tilghman | 2010-07-20 17:23:12 -0500 (Tue, 20 Jul 2010) | 7 lines

Delete IMAP messages in reverse order, to ensure reordering after each expunge does not cause deletion of the wrong message.

(closes issue ASTERISK-15240)
Reported by: noahisaac
Patches:
20100623__issue16350.diff.txt uploaded by tilghman (license 14)

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

http://svn.digium.com/view/asterisk?view=rev&revision=278261
By: Digium Subversion (svnbot) 2010-07-20 17:40:18

Repository: asterisk
Revision: 278275

_U trunk/
U trunk/apps/app_voicemail.c

------------------------------------------------------------------------
r278275 | tilghman | 2010-07-20 17:40:18 -0500 (Tue, 20 Jul 2010) | 14 lines

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

........
r278261 | tilghman | 2010-07-20 17:23:13 -0500 (Tue, 20 Jul 2010) | 7 lines

Delete IMAP messages in reverse order, to ensure reordering after each expunge does not cause deletion of the wrong message.

(closes issue ASTERISK-15240)
Reported by: noahisaac
Patches:
20100623__issue16350.diff.txt uploaded by tilghman (license 14)
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=278275
By: Digium Subversion (svnbot) 2010-07-20 17:43:50

Repository: asterisk
Revision: 278276

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

------------------------------------------------------------------------
r278276 | tilghman | 2010-07-20 17:43:50 -0500 (Tue, 20 Jul 2010) | 21 lines

Merged revisions 278275 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r278275 | tilghman | 2010-07-20 17:40:19 -0500 (Tue, 20 Jul 2010) | 14 lines

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

........
r278261 | tilghman | 2010-07-20 17:23:13 -0500 (Tue, 20 Jul 2010) | 7 lines

Delete IMAP messages in reverse order, to ensure reordering after each expunge does not cause deletion of the wrong message.

(closes issue ASTERISK-15240)
Reported by: noahisaac
Patches:
20100623__issue16350.diff.txt uploaded by tilghman (license 14)
........
................

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

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