A little more testing with hints from what has been happening and I am now at the point where I can reproduce the problem exactly time after time.  First things we can rule out, file caching by the Netware client, it happens exactly the same whether the caching is on of off.  The problem is related to the SSL errors we see on both Thunderbird and Mercury when Thunderbird is first started.  Specifically where on an initial attempt to connect, Thunderbird's error console reports "server does not support RFC5746, see CVE-2009-3555" and Mercury reports "SSL direct-connect failure form ....".  When Thunderbird starts up and attempts to connect, it fails with the error message noted, however the TB status bar is still "displaying Connected to test.mailserver.com".  I have always been somewhat suspect of messages in TB's status bar, however can not afford to spend the time to dig through the readily available source code to verify what is going on.  In any case if I at this point mark a number of messages in the inbox to delete in the inbox window on TB, and for the sake of test, I pick the oldest 24 so things will be looking the same in the logs as they were in the previous test and press the delete key, those 24 messages do appear to move to the trash folder on TB.  I switch to the trash folder in TB and at this point it now establishes a real connection with Mercury, which show up in the Current connections and status window on Mercury at this point.  If I at this point switch TB back to the inbox view, I now see all the messages I just deleted.  For the sake of this test, I do roll the mailbox back to its initial state by replacing all the files in the PMAIL folder of the test user in question to the exact state they were in before the test so we are always starting with everything at exactly the same point.  On the client side, the computer in question is always rolled back to a state where everything on it is back in a state where TB had successfully gotten it self in complete sync with no ongoing problems.  At this point if I delete files from the inbox in TB, they come back after switching folders. 

  If I look at the Mercury logs after this has happened and pick the oldest message that I deleted, I see it come back with a different UID.  Also if I look in the test user's PMAIL folder, I find the .CNM file from this message with the only difference between it and the original being the addition of a line as follows

X-PMFLAGS: 570949760 0 13 292DC404.CNM

This line is inserted just after all the rest of the headers and before the rest of the message, specifically the line 'This is a multi-part message in MIME format.'.

On the surface it appears that TB is moving the message to the trash folder offline and not marking it to be deleted because it does not have a connection to the server.  Once it does establish a connection to the server, which happens when the user takes some action, such as clicking on get mail or switching to a different folder, it now makes a connection and then syncs the message that it moved to the trash folder back to the server and the original is still in the inbox because a delete message was never sent due to the lack of a connection.  This would appear to be a bug in Thunderbird, however I will immediately get feedback from my users to the effect of "This never happens with other iMap servers". 

Gus

We have been using Mercury as our corporate mail server for many years and have had very few problems.  Recently we have been forced to convert traveling users from POP to IMAP and now are having many problems.  For way of information, Mercury is version 4.73 running on WinXP SP3 fully patched in NDS mode.  The XP that Mercury is running on has nothing else running on it and it and like the Netware server with the users home directories is a VM running on an Vmware ESXi server.  We have allocated 4G of ram and 4 processor cores to this machine, so it should not be starved for resources.  Remote users are running some combination of Cell phones, Thunderbird, Outlook and the email client in SugarCRM.  We have tried to instruct the remote users to use only one client at a time, however getting the message across to sales people is somewhat like herding cats. For what its worth, local users are almost all using Pmail in the network mode and are having none of these problems.

The problems we encounter most frequently are deleted messages re-appearing in the inbox of whichever email client.  It seems the worst with Thunderbird and the SugarCRM IMAP client, but they all do it.  A user will for example delete a message from the inbox with Thunderbird and a copy will end up in the Trash folder and later that message will re-appear in the inbox.  The user then deletes it again and a second copy ends up in the trash folder.  In some cases there will be four or more copies of the same message in the Trash folder.  A very similar situation occurs on moving a message from the inbox to any other folder.  We do try to get remote users to keep their inbox and trash folder as small as possible, however this does not seem to help.  These problems seem to occur whether the user is local with gigabit lan connections direct to the server or out in the rest of the world with flakey internet connections.

 The other problem is related to the email client in SugarCRM, which we know is not the best, however we are trying to work with Sugar support to improve.  When a user tries to check their mail with the Sugar email client, it will many times fail to login to Mercury.  Capturing packets and decoding them shows that the incoming packets have the user name correct, but several characters in the password are garbled.  It will do this 3 times in a row, same garbled password each time, then a short while later will try again and succeed.  We believe that this login problem is wholly  a Sugar problem, however I am a bit concerned as to whether all the traffic from the failed login attempts is causing a problem for Mercury.  On a probably related note, we will sometimes see login attempts by Thunderbird produce SSL direct-connect failures and then shortly later succeed.  Any comments on either of these situations would be appreciated.

 Questions that arise are, should we be running Mercury on some other version of Windows than XP or should that make no difference?  Is there something that can be done in configuration of either Mercury or the email clients that could improve the way things are working?  Any input on anything I can do to improve the situation would be greatly appreciated. We are getting close to the point where we are about to consider changing to something anything else due to all the problems.

 Gus Gustafson

> We have tried to instruct the remote users to use only one client at a time, however getting the message across to sales people is somewhat like
> herding cats.

You said it!

> The problems we encounter most frequently are deleted messages re-appearing in the inbox of whichever email client.  It seems the
> worst with Thunderbird and the SugarCRM IMAP client, but they all do it.  A user will for example delete a message from the inbox with
> Thunderbird and a copy will end up in the Trash folder and later that message will re-appear in the inbox.  The user then deletes it again
> and a second copy ends up in the trash folder.  In some cases there will be four or more copies of the same message in the Trash folder.
> A very similar situation occurs on moving a message from the inbox to any other folder.  We do try to get remote users to keep their inbox
> and trash folder as small as possible, however this does not seem to help.  These problems seem to occur whether the user is local with
> gigabit lan connections direct to the server or out in the rest of the world with flakey internet connections.

First of all Mercury does not support the IMAP4 option to allow deletes when there are multiple connections to the account.  The deletes only take place after all of the connections are closed with a logout.  Also, If the connection is broken and not logged out the the deleted flag is removed from the message. In this case you can see why those that are using multiple connections to the system find those deleted messages returning.

>
>  The other problem is related to the email client in SugarCRM, which we know is not the best, however we are trying to work with Sugar
> support to improve.  When a user tries to check their mail with the Sugar email client, it will many times fail to login to Mercury.
> Capturing packets and decoding them shows that the incoming packets have the user name correct, but several characters in the password are
> garbled.  It will do this 3 times in a row, same garbled password each time, then a short while later will try again and succeed.  We believe
> that this login problem is wholly  a Sugar problem, however I am a bit concerned as to whether all the traffic from the failed login attempts
> is causing a problem for Mercury.  On a probably related note, we will sometimes see login attempts by Thunderbird produce SSL direct-connect
> failures and then shortly later succeed.  Any comments on either of these situations would be appreciated.

The TLS/SSL connections may be failing.  You might try using STunnel with Mercury and have the e-mail clients use a direct SSL connection to see if this helps.

http://www.stunnel.org

For what it's worth I do not see why that the failed logins should be causing that much of a problem for MercuryI.

Thank you for the reply.  I am aware of the multiple client issue and have been trying to insure that the remote users stay with a single client at a time.  In at least one case I am sure that the user has only a single connection and that particular user has one of the worst problems, even when connected locally  with a very fast connection.  I believe I saw a point in another thread about Thunderbird never actually issuing a logout.  If that really is the case, we are going to have real problems ever making it work with Mercury.  I will look into the stunnel option to see if that resolves anything.

As to the failed logins, I was concerned of the possibility that the Novell client was imposing a delay on failed login attempts, slowing down other processing.  The server health logs are being overwhelmed by failed login attempt entries to the point that I would probably never see anything else in them if it were there.

Gus

Ok, tried stunnel and it appears that we are still having the same problems.  The biggest of which is when someone moves a message from the inbox to another folder, usually trash, it gets copied to the other folder but does not get removed from the inbox.  So far, this is being noticed with Thunderbird users, will see later in the day how it affects others.  Any suggestions are greatly appreciated at this point.

Would it be possible for you to post a MercuryI session log containing such a failed move action? Then we can see if it's the previously mentioned missing LOGOUT command or something else that is causing it.

/Rolf

I will try, however this will not be easy as there are over 60 users connecting all the time and it doesn't happen every time.  I will burn up a lot of disk space collecting logs and when it does happen, how do I sort through the whole mess to determine which one is the one that counts?  Any suggestions on how to go about collecting logs without dedicating my whole life to doing so?

Well, if I had this problem at our office I would try to identify a user that this frequently happens to and set up a test case that I could run for a short time, preferably at low-activity hours. This may or may not work in your environment, but that would be my strategy. (It's probably not a good thing to dedicate one's life to, anyway!)

/Rolf 

I think you can setup a second Mercury Installation on your local PC, or at a second machine, for one user (maybe your account). In addition you activate the Mercury D Modul on this machine to catch the emails for this one user from your original mailserver. This would minimize the logfiles, and the performance of your master server would not be decreased.

OK, I have a copy of the live mailserver running on an isolated network.  I installed a clean install of Thunderbird 3.1.10 on an XP box on that network.  Mercury is running in the NDS mode on another WinXP host and there is a Netware 6.5 server providing home drives and user authentication for mailboxes again on the same isolated network.  For the sake of test, I copy the whole PMAIL folder from the user with the biggest problem on the live system to a test users home directory on the isolated system.  This whole mess now has only one active user and no connection to the internet so I can control what happens.  I have been able to duplicate the problem a couple of times with the log running and have made a few observations.

1.  Thunderbird will not connect to the mail server when first opened without taking some other action even when Check for new messages at startup is checked, but that is a Thunderbird bug, for those who care.

2.  When TB connects we always get a line like this in the log

13:07:58.750: 22: Error -32 activating SSL session (locus 0, type 0, code 0, 'Invalid TLS extension list item header')

This line is associated with  a line on the on screen IMAP log stating "SSL direct-connect failure from (ip address)"

This ends up being a single log with 3 lines in it and a new one starts immediately thereafter and processing proceeds normally.  I am not sure if this is a problem, but I mention it anyway.

 3.  On the best capture I got of the problem happening, I open the inbox, highlight the 10 or so oldest messages in the inbox and press the delete key.  They disappear from the screen on TB.  I switch to the trash folder and see that they are there.  Switch back to inbox and they are back.  For what its worth, TB has run and gotten all its folders synced with the server on a previous session where nothing was moved or deleted in that session.  By the time I realize it has happened this time and I close the session so the log closes, the log is up to about 47mbytes, so we will not be posting the whole thing.  In any case, digging through the log, I see the first reference to the oldest message that had been in the inbox on line 242 of the log. 

13:09:03.671: << * 1 FETCH (UID 353 FLAGS (\Seen)
13:09:03.671: << )<cr><lf>

Skip down a ways and we get to the point where I had just deleted a few old messages

13:09:43.625: >> 33 uid copy 353:361,363:621,625,635,642,650,660:661,665:666,668:671 "Trash"<cr><lf>
13:09:44.687: << 33 OK COPY complete.<cr><lf>
13:09:44.703: >> 34 uid store 353:361,363:621,625,635,642,650,660:661,665:666,668:671 +FLAGS (\Deleted \Seen)<cr><lf>
13:09:47.968: << * 1 FETCH (UID 353 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 2 FETCH (UID 354 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 3 FETCH (UID 355 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 4 FETCH (UID 356 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 5 FETCH (UID 357 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 6 FETCH (UID 358 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 7 FETCH (UID 359 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 8 FETCH (UID 360 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 9 FETCH (UID 361 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 10 FETCH (UID 363 FLAGS (\SEEN \ANSWERED \DELETED))<cr><lf>
13:09:47.968: << * 11 FETCH (UID 617 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 12 FETCH (UID 618 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 13 FETCH (UID 621 FLAGS (\SEEN \ANSWERED \DELETED))<cr><lf>
13:09:47.968: << * 15 FETCH (UID 625 FLAGS (\SEEN \ANSWERED \DELETED))<cr><lf>
13:09:47.968: << * 20 FETCH (UID 635 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 23 FETCH (UID 642 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 25 FETCH (UID 650 FLAGS (\SEEN \ANSWERED \DELETED))<cr><lf>
13:09:47.968: << * 28 FETCH (UID 660 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 29 FETCH (UID 661 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 32 FETCH (UID 665 FLAGS (\SEEN \ANSWERED \DELETED))<cr><lf>
13:09:47.968: << * 33 FETCH (UID 666 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 34 FETCH (UID 668 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 35 FETCH (UID 670 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << * 36 FETCH (UID 671 FLAGS (\SEEN \DELETED))<cr><lf>
13:09:47.968: << 34 OK UID STORE complete.<cr><lf>
13:09:47.000: >> 35 uid store 674 +Flags (\Seen)<cr><lf>
13:09:47.078: << * 38 FETCH (UID 674 FLAGS (\SEEN))<cr><lf>
13:09:47.078: << 35 OK UID STORE complete.<cr><lf>
13:09:47.093: >> 36 noop<cr><lf>
13:09:47.093: << 36 OK NOOP complete.<cr><lf>

UID 353 is the one I am tracking, and up to this point all looks good, I think.  FYI, the noop is on line 3422 of the log.  Now I search for an expunge command, and the first one I find is on line 491453 of the log.  This is pretty much the last thing that happens as I close TB at the end of the test.  Note that this is about 4 minutes later.

13:13:42.515: >> 107 expunge<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 2 EXPUNGE<cr><lf>
13:13:42.515: << * 6 EXPUNGE<cr><lf>
13:13:42.515: << * 8 EXPUNGE<cr><lf>
13:13:42.515: << * 9 EXPUNGE<cr><lf>
13:13:42.515: << * 11 EXPUNGE<cr><lf>
13:13:42.531: << * 11 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << 107 OK EXPUNGE complete.<cr><lf>
13:13:42.546: >> 108 UID fetch 782:* (FLAGS)<cr><lf>
13:13:42.546: << 108 OK UID FETCH complete.<cr><lf>
13:13:42.640: >> 109 close<cr><lf>
13:13:42.656: << 109 OK CLOSE completed.<cr><lf>
13:13:42.656: >> 110 logout<cr><lf>
13:13:42.671: << * BYE IMAP4rev1 server terminating connection.<cr><lf>
13:13:42.671: << 110 OK LOGOUT completed.<cr><lf>

I am reasonably certain that by the time the expunge is issued, TB has decided to display the deleted message in the inbox yet again.  If I re-open TB and delete the message again, I now have two copies of the message in the trash folder.  If I look at the account of a user that this has happened to on the live network with WinPmail, I see that the problem message(s) exist in both the inbox and the trash folder.  I have seen similar things happen with other mailers that use a differently named trash folder.

Things I have learned in the whole mess.  If  I go into the Thunderbird config editor and change the mail.imap_expunge_after_delete option from false to true and change mail.imap.expunge_option from 0 to 1 the frequency of the problem is dramatically reduced, but not totally eliminated.  What else should I be looking for in the intervening 400000+ lines of log?  Some days I think the problem is the worst for users with not so good internet connections and other days I could swear it is the fastest connections, and it is possible that neither is relevant.  The 3 computers involved in this test were all virtual machines on a VMware box with very fast virtual connections between them, no data actually traveled on a wire.  Any input or suggestions are greatly appreciated.

Gus

Splendid, now we have something to work with! First of all we can conclude that this is not similar to the case with the missing LOGOUT command discussed in another thread; this session ends with EXPUNGE, CLOSE and LOGOUT.

The SSL session error means that Thunderbird tried to establish a secure SSL connection, and when that failed it simply fell back to unencrypted communication. This will not be a problem unless your local security policy absolutely requires SSL.

Do I understand you correctly when you say "I am reasonably certain that by the time the expunge is issued, TB has decided to display the deleted message in the inbox yet again" that it means that the deleted messages have reappeared in Thunderbird already before the program is closed down? If so, has there in the meantime been any SEARCH or FETCH commands sent to the server that returned a reference to any of the deleted messages?

/Rolf

In regards to the SSL error the session that finally establishes is still an SSL session for what that's worth.  Disable plaintext logins for non-ssl connections is checked and the client I have been testing with is set for plain text logins.  Watching the raw packets with Wireshark confirms that they are indeed encrypted.

The  stuff around line 3400+ in the logs is the last reference to UID 353 in the log.  After I deleted the group of messages, I switched to the trash folder, saw that they were indeed displaying there, and soon thereafter switched back to the inbox and see that all of these messages have come back.   I guess I should have said I was sure as I did wait for a while to see if there was going to be anymore network traffic after seeing these come back into the inbox before I closed TB.  If I search for something unique to that message, I find it being referenced by a different UID and I believe in the trash folder after that point.  All 'search 353' or 'fetch 353' are before the point of deletion at about line 3400+ in the log.

Gus

The logs excerpts suggest that 24 messages were flagged as deleted, but only 14 expunged. Were all 24 present the next time Thunderbird was started? If the messages had reappeared in Thunderbird before the EXPUNGE command was sent that indicates that Thunderbird for some reason has renewed the message list for the inbox in between, and I was curious if there was any trace of that in the log.

Is there any process on the server that could interfere with Mercury's file access, for instance some kind of anti-malware program?

/Rolf

The number of messages that I deleted in the test is probably much closer to 14 than 24, unfortunately I did not count as I was running the test.  I have a copy of this mailbox that I can easily restore to the state it was in before I started testing.  I selected several messages to delete because the problem occurs more frequently with mass moves than with a single, however that does happen also.  Note that this does not happen every single time, so I suspect that it is somewhat timing related.  I am sure that the messages all re-appeared in the inbox before the expunge was issued.  The expunge only occurred just as TB was being shut down.  I waited until there was no activity before I closed it. 

I removed everything else that was running on the live server yesterday morning, doing so does not seem to have made any difference.  The only processes running on the test server were Mercury and Clamwall.  Everything else was either un-installed or killed one way or the other.  File access from the Mercury machine to the Netware server is rock solid and very fast, no problems noted.  Mercury has full rights to the folders in question on the Netware server and no Windows access rights have been altered on the Mercury box.

Mm OK. This is the command that Thunderbird sends to the server:

uid store 353:361,363:621,625,635,642,650,660:661,665:666,668:671 +FLAGS (\Deleted \Seen)

The reply from the server lists 24 messages that match the given UIDs, and confirms that the command has completed successfully:

OK UID STORE complete.

If you had marked less than 24 messages when issuing the delete command there are some very strange things going on, and we should probably check the part before the UID STORE command to see what UIDs the server has actually presented to Thunderbird.

Are there no lines in the log that could explain why Thunderbird later reverts to the initial message list? Look for another SELECT INBOX followed by a lot of FETCH commands.

/Rolf

Thanks for the hints.  I am at the wrong location today.  Will look when I am back in the other office in the morning.

Gus

This might help find out more.  I used a text editor to search for all lines that begin with ": >> " to pick out commands sent from TB to Mercury and out of the nearly 500000 lines I got the following 117 lines.  It appears to me that the deleted message when  it reappears in the inbox is coming back with a different UID.  I realize that this is just one direction, but was easy to filter out of the whole mess.  The number in the first column is the line number that this response was found at, inserted by the editor.  If we need to see the response to any of these let me know and I will find it in the log file and post here.  The authenticate line is deliberately altered.

4          13:09:03.156: >> 1 capability<cr><lf>
7          13:09:03.218: >> 2 authenticate plain<cr><lf>
9          13:09:03.234: >> ******************************<cr><lf>
11         13:09:03.359: >> 3 lsub "" "*"<cr><lf>
15         13:09:03.390: >> 4 list "" "INBOX"<cr><lf>
18         13:09:03.406: >> 5 list "" "Trash"<cr><lf>
21         13:09:03.421: >> 6 create "Trash"<cr><lf>
23         13:09:03.437: >> 7 select "Trash"<cr><lf>
31         13:09:03.468: >> 8 UID fetch 1:* (FLAGS)<cr><lf>
233        13:09:03.640: >> 9 select "INBOX"<cr><lf>
241        13:09:03.671: >> 10 UID fetch 1:* (FLAGS)<cr><lf>
337        13:09:03.703: >> 11 UID fetch 353:361,363:771 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])<cr><lf>
884        13:09:04.031: >> 12 UID fetch 652,691,695,703,710,734,771 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
1959       13:09:04.250: >> 13 UID fetch 617,624,628,635,638,644,653,661,665,668,671,674,771 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>)<cr><lf>
2768       13:09:04.640: >> 14 UID fetch 617 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>)<cr><lf>
2848       13:09:10.218: >> 15 noop<cr><lf>
2850       13:09:10.234: >> 16 UID fetch 772:* (FLAGS)<cr><lf>
2852       13:09:22.750: >> 17 UID fetch 353 (BODYSTRUCTURE)<cr><lf>
2856       13:09:22.781: >> 18 UID fetch 353 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[1.1.MIME] BODY.PEEK[1.2.MIME] BODY.PEEK[2.MIME])<cr><lf>
2907       13:09:23.875: >> 19 UID fetch 353 (BODY.PEEK[1.1])<cr><lf>
2917       13:09:23.906: >> 20 UID fetch 353 (BODY.PEEK[1.2])<cr><lf>
2981       13:09:26.015: >> 21 UID fetch 363 (BODYSTRUCTURE)<cr><lf>
2985       13:09:26.031: >> 22 UID fetch 363 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[2.MIME] BODY.PEEK[3.MIME])<cr><lf>
3020       13:09:26.078: >> 23 UID fetch 363 (BODY.PEEK[1])<cr><lf>
3038       13:09:26.109: >> 24 UID fetch 363 (BODY.PEEK[2])<cr><lf>
3054       13:09:34.328: >> 25 UID fetch 353 (BODY.PEEK[1.1])<cr><lf>
3064       13:09:34.359: >> 26 UID fetch 353 (BODY.PEEK[1.2])<cr><lf>
3128       13:09:41.062: >> 27 uid store 353:361,363:621,625,635,642,650,660:661,665:666,668:671 +Flags (\Seen)<cr><lf>
3154       13:09:43.328: >> 28 UID fetch 674 (BODYSTRUCTURE)<cr><lf>
3158       13:09:43.359: >> 29 UID fetch 674 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[1.1.MIME] BODY.PEEK[1.2.MIME] BODY.PEEK[2.MIME])<cr><lf>
3212       13:09:43.453: >> 30 UID fetch 674 (BODY.PEEK[1.1])<cr><lf>
3291       13:09:43.500: >> 31 UID fetch 674 (BODY.PEEK[1.2])<cr><lf>
3391       13:09:43.625: >> 33 uid copy 353:361,363:621,625,635,642,650,660:661,665:666,668:671 "Trash"<cr><lf>
3393       13:09:44.703: >> 34 uid store 353:361,363:621,625,635,642,650,660:661,665:666,668:671 +FLAGS (\Deleted \Seen)<cr><lf>
3419       13:09:47.000: >> 35 uid store 674 +Flags (\Seen)<cr><lf>
3422       13:09:47.093: >> 36 noop<cr><lf>
3424       13:09:47.109: >> 37 UID fetch 772:* (FLAGS)<cr><lf>
3426       13:09:50.890: >> 38 select "Trash"<cr><lf>
3434       13:09:50.953: >> 39 UID fetch 1:* (FLAGS)<cr><lf>
3684       13:09:50.046: >> 40 UID fetch 762:785 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])<cr><lf>
3962       13:09:50.250: >> 41 UID fetch 776,781 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
4321       13:09:53.062: >> 42 select "INBOX"<cr><lf>
4329       13:09:53.187: >> 43 UID fetch 1:* (FLAGS)<cr><lf>
4425       13:09:53.218: >> 44 UID fetch 772:781 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])<cr><lf>
4530       13:09:53.328: >> 45 UID fetch 631 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
4813       13:09:53.390: >> 46 UID fetch 674 (BODY.PEEK[1.1])<cr><lf>
4892       13:09:53.437: >> 47 UID fetch 674 (BODY.PEEK[1.2])<cr><lf>
4992       13:10:23.781: >> 48 select "Trash"<cr><lf>
5000       13:10:24.828: >> 49 UID fetch 1:* (FLAGS)<cr><lf>
5250       13:10:24.906: >> 50 UID fetch 772,774:775 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
6329       13:10:24.109: >> 51 UID fetch 773,779 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
7301       13:10:24.296: >> 52 STATUS "Drafts" (UIDNEXT MESSAGES UNSEEN RECENT)<cr><lf>
7304       13:10:24.312: >> 53 UID fetch 782,784:785 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
8003       13:10:24.437: >> 54 UID fetch 771 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
8743       13:10:24.671: >> 55 STATUS "Sent" (UIDNEXT MESSAGES UNSEEN RECENT)<cr><lf>
8746       13:10:24.687: >> 56 UID fetch 763,767,769:770 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
9128       13:10:24.781: >> 57 select "Sent"<cr><lf>
9136       13:10:25.843: >> 58 UID fetch 1:* (FLAGS)<cr><lf>
9502       13:10:25.937: >> 59 UID fetch 2:4,68:72,134:135,140,149,176 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])<cr><lf>
9629       13:10:25.031: >> 60 select "Trash"<cr><lf>
9637       13:10:25.093: >> 61 UID fetch 1:* (FLAGS)<cr><lf>
9887       13:10:25.187: >> 62 UID fetch 765 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
11960      13:10:25.531: >> 63 UID fetch 764 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
14182      13:10:26.921: >> 64 UID fetch 762 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
16325      13:10:26.484: >> 65 UID fetch 778 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
18730      13:10:27.890: >> 66 UID fetch 777 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
21255      13:10:27.343: >> 67 UID fetch 783 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
31253      13:10:29.421: >> 68 UID fetch 780 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
42902      13:10:31.718: >> 69 UID fetch 766 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
55718      13:10:34.421: >> 70 UID fetch 768 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
76677      13:10:58.984: >> 71 select "INBOX"<cr><lf>
76685      13:10:58.078: >> 72 UID fetch 1:* (FLAGS)<cr><lf>
76781      13:10:58.156: >> 73 UID fetch 663,675 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
77698      13:10:58.359: >> 74 UID fetch 628,630,637,673 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
79023      13:10:58.609: >> 75 STATUS "Trash" (UIDNEXT MESSAGES UNSEEN RECENT)<cr><lf>
79026      13:10:58.625: >> 76 UID fetch 638,644,653 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
79457      13:10:58.734: >> 77 UID fetch 781 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
80197      13:10:59.921: >> 78 UID fetch 772,775:776,778 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
80579      13:10:59.031: >> 79 UID fetch 715 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
83083      13:10:59.562: >> 80 UID fetch 761 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
84841      13:11:00.921: >> 81 UID fetch 773 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
86914      13:11:00.421: >> 82 UID fetch 780 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
89136      13:11:01.937: >> 83 UID fetch 777 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
91279      13:11:01.531: >> 84 UID fetch 674 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
93787      13:11:02.093: >> 85 UID fetch 624 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
96888      13:11:03.046: >> 86 UID fetch 662 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
107987     13:11:05.796: >> 87 UID fetch 779 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
120803     13:11:08.796: >> 88 UID fetch 626 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
135110     13:11:11.671: >> 89 UID fetch 774 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
156069     13:11:16.203: >> 90 select "Sent"<cr><lf>
156077     13:11:16.265: >> 91 UID fetch 1:* (FLAGS)<cr><lf>
156443     13:11:16.375: >> 92 UID fetch 140 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
167103     13:11:18.656: >> 93 UID fetch 2 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
179747     13:11:21.250: >> 94 UID fetch 149 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
199677     13:11:26.937: >> 95 UID fetch 71 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
221209     13:11:31.000: >> 96 UID fetch 134 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
243362     13:11:36.421: >> 97 UID fetch 72 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
266859     13:11:42.984: >> 98 UID fetch 68 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
292151     13:11:48.828: >> 99 UID fetch 69 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
317443     13:11:53.765: >> 100 UID fetch 70 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
344362     13:12:00.062: >> 101 UID fetch 135 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
382777     13:12:09.203: >> 102 UID fetch 176 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
425221     13:12:19.421: >> 103 UID fetch 4 (UID RFC822.SIZE BODY.PEEK[])<cr><lf>
491346     13:13:25.000: >> 104 STATUS "INBOX" (UIDNEXT MESSAGES UNSEEN RECENT)<cr><lf>
491349     13:13:25.046: >> 105 select "INBOX"<cr><lf>
491357     13:13:25.125: >> 106 UID fetch 1:* (FLAGS)<cr><lf>
491453     13:13:42.515: >> 107 expunge<cr><lf>
491469     13:13:42.546: >> 108 UID fetch 782:* (FLAGS)<cr><lf>
491471     13:13:42.640: >> 109 close<cr><lf>
491473     13:13:42.656: >> 110 logout<cr><lf>
 

The first thing to check would be the values of server replies containing UIDVALIDITY.

The reply to UID fetch 1:* (FLAGS) on line 241 should list all messages found in the inbox before the delete.

The reply to the same command on line 4329 should show inbox contents after the delete. It looks like 10 new messages are found (772:781), right? That's not the number of deleted or expunged messages seen in the earlier log lines, though.

There is another UID fetch command on line 491357 that should contain the same messages as the previous one. The UID fetch after the expunge command (line 491469) did most likely not return any messages.

/Rolf

The replies just after 241 do list the contents of the inbox.  There were quite a few messages in it when I started.  There were a large number of messages in the trash folder when I started also.

And yes there are more messages in the inbox just after the delete.  The problem is that they are copies of some of the messages that were just deleted.  They could not have come from elsewhere, nothing else other then the server and the one client I was testing with have access to this setup.  One thing I have noticed about the way Thunderbird works when deleting (moving a message to the trash folder) is that locally it is deleted from the local copy of the inbox and then TB downloads the copy it made on the server from the server trash folder to the local trash folder.  Not exactly the most efficient, but that complaint needs to go to the Thunderbird folks.

 The UID fetch just after 491357 sees all the same files as the previous one.

 All the UIDVALIDITY commands in the whole log:

27         13:09:03.453: << * OK [UIDVALIDITY 1306506325] UID Validity<cr><lf>
237        13:09:03.656: << * OK [UIDVALIDITY 1303479618] UID Validity<cr><lf>
3430       13:09:50.937: << * OK [UIDVALIDITY 1306506325] UID Validity<cr><lf>
4325       13:09:53.171: << * OK [UIDVALIDITY 1303479618] UID Validity<cr><lf>
4996       13:10:24.812: << * OK [UIDVALIDITY 1306506325] UID Validity<cr><lf>
9132       13:10:25.828: << * OK [UIDVALIDITY 1303480158] UID Validity<cr><lf>
9633       13:10:25.078: << * OK [UIDVALIDITY 1306506325] UID Validity<cr><lf>
76681      13:10:58.046: << * OK [UIDVALIDITY 1303479618] UID Validity<cr><lf>
156073     13:11:16.250: << * OK [UIDVALIDITY 1303480158] UID Validity<cr><lf>
491353     13:13:25.093: << * OK [UIDVALIDITY 1303479618] UID Validity<cr><lf>

and the last several lines showing what happens at the expunge

13:13:42.515: >> 107 expunge<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 1 EXPUNGE<cr><lf>
13:13:42.515: << * 2 EXPUNGE<cr><lf>
13:13:42.515: << * 6 EXPUNGE<cr><lf>
13:13:42.515: << * 8 EXPUNGE<cr><lf>
13:13:42.515: << * 9 EXPUNGE<cr><lf>
13:13:42.515: << * 11 EXPUNGE<cr><lf>
13:13:42.531: << * 11 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << * 13 EXPUNGE<cr><lf>
13:13:42.531: << 107 OK EXPUNGE complete.<cr><lf>
13:13:42.546: >> 108 UID fetch 782:* (FLAGS)<cr><lf>
13:13:42.546: << 108 OK UID FETCH complete.<cr><lf>
13:13:42.640: >> 109 close<cr><lf>
13:13:42.656: << 109 OK CLOSE completed.<cr><lf>
13:13:42.656: >> 110 logout<cr><lf>
13:13:42.671: << * BYE IMAP4rev1 server terminating connection.<cr><lf>
13:13:42.671: << 110 OK LOGOUT completed.<cr><lf>
13:13:42.671: 19: SSL write error -24 (locus 0, type 0, code 0, 'Received SSL alert message: Close notify')
13:13:42.671: --- Connection closed normally at Tue Jun 07 13:13:42 2011. ---

One more note on the SSL stuff, when using Mercury's built in SSL stack, when Thunderbird first opens and produces the SSL direct-connect failure message on Mercury, the error log on Thunderbird contains the line

server does not support RFC 5746, see CVE-2009-3555

If I use stunnel, there are no errors on connect.  While stunnel appears to work well, as far as Mercury is concerned every connection is coming from localhost.   This kills the ability to use Mercury's built in connection controls and logging is not as clean either.  As to the re-appearing emails, those happen either way.  As I mentioned in an earlier post, setting mail.imap.expunge_after_delete to true in TB dramatically reduces the occurrence of this kind of problem, but does not eliminate it.  This particular test was run with that var set to false.  With a good connection it takes too many tries to get it to happen for realistic testing when it is set to true.  Note that this does not happen every time, and having watched it for some time, I haven't a clue what makes it decide to happen.  Having a crappy connection in the terminal of some airport seems to exasperate the problem.  Some of us would just call this a corollary of Murphy's law.  This test was run with the native SSL stack in Mercury.  Experience with a number of users in the field and running with stunnel for SSL produces the same results.

Gus

So if I understand that correctly the UIDVALIDITY value for each folder is unchanged during the session, which is what it normally should be.

It seems we have three unexpected things happening here: why were 24 messages flagged as deleted when you hadn't marked that many, why are 10 new messages found in the listing after delete flags have been set, and why were only 14 messages expunged at session end?

Would it be right to assume that 10 of the UIDs that were flagged as deleted are missing in the second INBOX listing (ore rather replaced with entries with new UIDs and no delete flag set)? How many messages could it have been that you actually marked for deletion?

/Rolf