[Home]

Summary:ASTERISK-16069: [patch] Sequencing numbers of IMAP email messages is incorrect
Reporter:SplatNIX (uxbod)Labels:
Date Opened:2010-05-07 08:28:16Date Closed:2010-05-17 14:42:41
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail/IMAP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 17306_1.diff
( 1) imap-debug.txt
( 2) vmissue.png
Description:Left six voicemails which were all successfully delivered to the IMAP server.  On checking them the sequence numbers were not sequential.  Screen shot attached.
Comments:By: SplatNIX (uxbod) 2010-05-07 09:11:37

I believe this issue is entangled with http://issues.asterisk.org/view.php?id=16350 and causing VMs not to be deleted as-well from the IMAP store.
By: SplatNIX (uxbod) 2010-05-07 09:12:52

Attaching a Zimbra IMAP debug trace.  I emptied my VM folder and then left two new VMs.  On checking the IMAP folder they were labelled as VM-1 and VM-3.  The trace happened while I performed this test.
By: SplatNIX (uxbod) 2010-05-07 10:28:00

What I see in the VMs stored, from the headers and MIME details, are the following:

VoiceMail Number 1
------------------
X-Asterisk-VM-Message-Num: 1
Content-Type: audio/x-WAV; name="msg0000.WAV"

VoiceMail Number 2
------------------
X-Asterisk-VM-Message-Num: 3
Content-Type: audio/x-WAV; name="msg0002.WAV"

And when you delete the messages the first one goes fine, but when it looks for message number 2 it never finds it as it has been stored as number 3.  It is though msgnum in app_voicemail.c is being incremented in the wrong place or a search is being performed twice before the IMAP message is stored.
By: SplatNIX (uxbod) 2010-05-07 10:56:33

To narrow the search I changed all references in the procedure make_email_file() from msgnum + 1 to msgnum.  I left two messages again and the first one was marked at ID0 and the second as ID2.  This would point me to believe that msgnum is being incorrectly advanced before writing the VM to IMAP and due to a search being performed twice somewhere.
By: Leif Madsen (lmadsen) 2010-05-07 11:46:20

Thanks for tracking that down! Now ASTERISK-15240 makes a lot more sense! :)
By: Noah Miller (noahisaac) 2010-05-07 12:01:14

Indeed, very interesting.  What kinds of calls cause the id to be advanced?
By: SplatNIX (uxbod) 2010-05-07 12:08:04

Normal VMs :) In app_voicemail.c this, IMHO, is where it is performing the search for IMAP stored messages:

pgm = mail_newsearchpgm ();
               hdr = mail_newsearchheader ("X-Asterisk-VM-Extension", (char *)(!ast_strlen_zero(vmu->imapvmshareid) ? vmu->imapvmshareid : mailbox));
               hdr->next = mail_newsearchheader("X-Asterisk-VM-Context", (char *) S_OR(context, "default"));

and that is contained within proc __messagecount().  If no VMs are there then I see why msgcount + 1 would be used to increment from zero too one.  Yet if one has already been left then why would msgcount be two already ? That is the mystery and I do not know enough 'C' to be able to work out the code :(  Anything I can do to help I will as this is causing our clients quite a bit of pain.  I did raise it with Zimbra support who checked their IMAP code and came to the same conclusion something was happening on the Asterisk side :- http://bugzilla.zimbra.com/show_bug.cgi?id=46704
By: Noah Miller (noahisaac) 2010-05-07 12:50:39

I can tell you that I don't think those searches are incrementing the id.  I've modified those particular lines (see bug: 15670) to be only a single search, and the issue still exists.  These searches are performed every time VoicemailMain() is called.

uxbod: If you need a workaround for your clients: I'm running 1.6.1.18 on the client that's affected by this bug, but I'm using a very slightly modified version of the app_voicemail.c from 1.6.1.6.  It seems to be totally stable, and you can successfully delete voicemails!
By: SplatNIX (uxbod) 2010-05-07 13:52:43

Delete yes, but it the sequencing correct ? How have you modified app_voicemail ? would be interested to see your patch; please :)
By: Noah Miller (noahisaac) 2010-05-07 15:04:07

Haven't checked the sequencing with my older version of app_voicemail, but I think it's probably correct, since the deleting works.

I think you can get away with using the unpatched 1.6.1.6 app_voicemail.c with the latest version of asterisk 1.6.1.x.  If you want the version that I'm using, I can email it to you.  Just let me know what your address is (Is it possible to look up another user's email addresses in Mantis?).  Two important patches that I add to the 1.6.1.6 version: patch to correctly remove temporary greetings for IMAP voicemail, patch to access IMAP voicemails that were not originally sent to the recipient's context/extension.
By: SplatNIX (uxbod) 2010-05-10 04:59:40

uxbod [at] splatnix.net

If you could send the patches that would be great and I will give them a whirl.
By: SplatNIX (uxbod) 2010-05-10 09:15:14

I am slowly honing in on the issue by adding more debug statements.  What I know so far is that if you have left one VM when the procedure inboxcount2() returns it is saying that newmsgs is already set at two!

I have added a before and after to inboxcount():

static int inboxcount(const char *mailbox, int *newmsgs, int *oldmsgs)
{
       ast_log(LOG_DEBUG, "InboxCount - Before : %s New Msgs : %d Old Msgs : %d\n",mailbox, *newmsgs, *oldmsgs);
       int urgentmsgs = 0;
       int res = inboxcount2(mailbox, &urgentmsgs, newmsgs, oldmsgs);
       if (newmsgs) {
               *newmsgs += urgentmsgs;
       }
       ast_log(LOG_DEBUG, "InboxCount - After : %s New Msgs : %d Old Msgs : %d Urgent : %d\n",mailbox, *newmsgs, *oldmsgs, urgentmsgs);
       return res;
}

I deleted all VMs in the IMAP mailbox and then connected again and left one VM.  Here is what was in the debug:

[May 10 15:57:02] DEBUG[17634] app_voicemail.c: InboxCount - Before : 123@voicemail New Msgs : 139291902 Old Msgs : 1
[May 10 15:57:03] DEBUG[17634] app_voicemail.c: InboxCount - After : 123@voicemail New Msgs : 0 Old Msgs : 0 Urgent : 0

The single VM appeared in the IMAP folder.  I then left another VM and look what happens this time!

[May 10 15:57:17] DEBUG[17636] app_voicemail.c: InboxCount - Before : 123@voicemail New Msgs : 139291902 Old Msgs : 1
[May 10 15:57:17] DEBUG[17636] app_voicemail.c: InboxCount - After : 123@voicemail New Msgs : 2 Old Msgs : 0 Urgent : 1

I now have two VMs with called VM-1 and VM-3!


By: SplatNIX (uxbod) 2010-05-10 11:06:46

For some reason it is finding a urgent message and then hits:

       if (newmsgs) {
               *newmsgs += urgentmsgs;
       }

Yet the only thing which was in the folder was one VM message.


By: SplatNIX (uxbod) 2010-05-10 13:03:26

It is definately something to do with checking urgent messages within the IMAP folder.  For some reason urgentmsgs is being set to the number of oldmsgs.
By: SplatNIX (uxbod) 2010-05-10 14:01:18

Sorry; I cannot find where urgentmsgs is being set incorrectly though that *is* the reason why the counter is incorrect.  Will need one of the devs to take a look as my C is not good enough :(
By: SplatNIX (uxbod) 2010-05-10 22:30:02

Took another look and it would appear that __messagecount() is accessed via the method messagecount(); which that function does not look correct:

static int messagecount(const char *context, const char *mailbox, const char *folder)
{
       if (ast_strlen_zero(folder) || !strcmp(folder, "INBOX")) {
               return __messagecount(context, mailbox, "INBOX") + __messagecount(context, mailbox, "Urgent");
       } else {
               return __messagecount(context, mailbox, folder);
       }
}


If you have specified a folder that is *NOT* called INBOX then should it not be using __messagecount() in the else section of the IF statement?  I am assuming the code should in-fact be:

static int messagecount(const char *context, const char *mailbox, const char *folder)
{
       if (ast_strlen_zero(folder) || strcmp(folder, "INBOX")) {
               return __messagecount(context, mailbox, "INBOX") + __messagecount(context, mailbox, "Urgent");
       } else {
               return __messagecount(context, mailbox, folder);
       }
}
By: Elazar Broad (ebroad) 2010-05-10 23:40:40

That logic is correct, strcmp[1] returns 0 when str1 == str2 and ast_strlen_zero[2] returns 1 when the string is null. So in this case, if (folder != null) = 0 and strcmp(folder, "INBOX") = 0, !0(which is 1) || 0 = 1, which would evaluate to True.
With that said, if folder is null, this function could potentially pass a null value to __messagecount(), i.e. folder == null would be 1, and !strcmp(folder, "INBOX") would be !1 or -1 which would be 0, meaning we would still hit  return __messagecount(context, mailbox, "INBOX") + __messagecount(context, mailbox, "Urgent");. IMHO, I would rewrite it like this:

static int messagecount(const char *context, const char *mailbox, const char *folder)
{
   if (!(ast_strlen_zero(folder)) {  
       if (!strcmp(folder, "INBOX")) {
               return __messagecount(context, mailbox, "INBOX") + __messagecount(context, mailbox, "Urgent");
       } else {
               return __messagecount(context, mailbox, folder);
       }
   } else {
     return -1;
   }
}






[1] http://www.cplusplus.com/reference/clibrary/cstring/strcmp/
[2] http://www.asterisk.org/doxygen/trunk/strings_8h-source.html#l00063
By: SplatNIX (uxbod) 2010-05-11 07:14:40

Agreed; completely my mistake.  I did try the code though:

if (!(ast_strlen_zero(folder))

was missing a trailing close bracket.  This made no difference at all to the functionality.  Will add some more debug lines when I get chance today.
By: Elazar Broad (ebroad) 2010-05-11 21:12:12

I just realized something, folder_int() has no case for "Urgent" which means:
return __messagecount(context, mailbox, "INBOX") + __messagecount(context, mailbox, "Urgent");
is really INBOX + INBOX, since the fallback in folder_int() is 0 which is INBOX. Try this, add the following below "Cust5" in folder_int():
---
else if (!strcasecmp(folder, "Urgent"))
return 11;
---

elazar
By: SplatNIX (uxbod) 2010-05-12 03:14:27

Oh so simple :) Yep that indeed resolved the issue.  To test I left two VMs and the sequence numbers were correct.  I then marked them as both read in the IMAP folder and left another one; correct sequence was actioned.  I then deleted three of the VMs, leaving only one, and then left a new VM; for which the sequence numbers were correct.  Thank you (And I even looked at that bit of code! :))
By: Elazar Broad (ebroad) 2010-05-12 07:43:18

Sweet! Thanks for testing, uxbod. Now, I have one more request since I do not have an IMAP setup, can you test urgent messages as well just to make sure they are counted properly?

thanks,
elazar
By: SplatNIX (uxbod) 2010-05-12 08:24:27

Argh! Urgent messages are now showing the same symptom as the original issue :(
By: Elazar Broad (ebroad) 2010-05-12 11:33:07

In __messagecount() change:
---
if (fold == 0) { /* INBOX */
return vms_p->newmessages;
}
if (fold == 1) { /* Old messages */
return vms_p->oldmessages;
}
if (fold == 11) {/*Urgent messages*/
return vms_p->urgentmessages;
}
---
to this
---
               if (fold == 0 && urgent == 0) { /* INBOX */
return vms_p->newmessages;
}
if (fold == 1) { /* Old messages */
return vms_p->oldmessages;
}
if (fold == 0 && urgent == 1) {/*Urgent messages*/
return vms_p->urgentmessages;
}
By: SplatNIX (uxbod) 2010-05-12 11:43:05

Replaced code and now looks like:

if (vms_p) {
               ast_debug(3, "Returning before search - user is logged in\n");
               if (fold == 0 && urgent == 0) { /* INBOX */
                       return vms_p->newmessages;
               }
               if (fold == 1) { /* Old messages */
                       return vms_p->oldmessages;
               }
               if (fold == 0 && urgent == 1) {/*Urgent messages*/
                       return vms_p->urgentmessages;
               }
       }

The same problem persists.  Two VMs left and they were labelled:

X-Asterisk-VM-Message-Num: 1
X-Asterisk-VM-Server-Name:
X-Asterisk-VM-Context: voicemail

-- and --

X-Asterisk-VM-Message-Num: 3
X-Asterisk-VM-Server-Name:
X-Asterisk-VM-Context: voicemail
By: Elazar Broad (ebroad) 2010-05-12 11:51:37

Both urgent?



PS. ebroad on IRC
By: SplatNIX (uxbod) 2010-05-12 12:05:50

Yes, I set the 'U' flag on the extension.
By: SplatNIX (uxbod) 2010-05-12 12:07:14

exten => 1002,1,VoiceMail(1001@voicemail,uU)
exten => 1002,n,Hangup()
By: Elazar Broad (ebroad) 2010-05-12 12:10:37

Do you have imapfolder set to anything for this user?
By: SplatNIX (uxbod) 2010-05-12 14:12:11

imapfolder=VoiceMailOffice
By: Elazar Broad (ebroad) 2010-05-13 11:05:14

Can you change the following block in __messagecount() from :

if (fold != 1) {
pgm->unseen = 1;
pgm->seen = 0;
}

to

if (fold != 1) {
pgm->unseen = 1;
pgm->seen = 0;
                       pgm->flagged = 0;
pgm->unflagged = 1;

}
By: SplatNIX (uxbod) 2010-05-13 11:13:14

That appears to fix the sequencing issue on urgent messages.  I believe we need to define a few test cases now to ensure that all is working as expected.  For reference this does not resolve issue ASTERISK-1616350.  I left three urgent VMs, connected to CM, and deleted all three and then exited correctly.  VM2 was left in the IMAP folder.
By: Elazar Broad (ebroad) 2010-05-17 14:42:41

I believe this issue has been resolved with the SVN commit for issue 17135(https://issues.asterisk.org/view.php?id=17135). Please re-open this issue if it continues to remain a problem.

elazar