Reappearing emails - IMAP trace

Tue Mar 8 16:57:29 UTC 2016

A few days back, I sent an overview of this problem, but received no 
responses.   Since then, I have run dozens of traces to isolate the 
problem, difficult because there are timing issues involved.  I have 
finally nailed it down.  If this is not the proper place to report such 
bugs or if someone knows that this bug has been fixed, please let me 
know.  As I noted in my earlier post, we have been running Dovecot 
2.2.10 with a pair of CentOS 7 boxes with replications for the past 
year.  We have been quite happy with the performance and reliability.

Recently we received a report that emails could reappear in the INBOX 
after being deleted.  After running a pile of traces, I determined that 
the problem was strangely related to replications.  For the purposes of 
this discussion, I will refer to the two symmetric replicating servers 
as A and B.  Further, let us assume that during "normal" operation, all 
the emails are delivered to A via SMTP and are replicated to B.  Under 
those assumptions, if the IMAP user connects to A (where the messages 
were originally delivered), there is no problem, at least no problem I 
was able to find.  The problem I am describing only arises if the IMAP 
user connects to B.  Connecting to B has never presented any other 
problems that I am aware of.

The test for which I have provided the trace starts with a test mailbox 
containing only 3 unread messages in the INBOX.  Moving 1 of the unread 
messages to Trash is all that is needed to reproduce the problem.  
Remember this is ONLY a problem if the IMAP sessions do not connect to 
the server to which the messages were originally delivered.  Also, I 
found that there is a timing window.  The critical IMAP commands are:

    UID STORE xxx +FLAGS.SILENT (\Seen)
    UID MOVE xxx Trash

If you introduce a large enough delay (I arbitrarily chose 5 seconds) 
between those two commands, there is no problem. Presumably this has to 
do with the two boxes syncing up some critical data structure.

It takes a short time for the message that was moved to Trash to 
reappear in the INBOX.   The trace initially shows the number of 
messages going from 3 to 2 when the message is moved to Trash, but a 
second or so later, the message count goes back up to 3. Interestingly, 
the reappearing message shows back up as Unseen in the INBOX but a 
duplicate copy of it stays in Trash as Seen.

Dragging unread messages to Trash may not be polite, but it is 
technically acceptable.

Regarding the trace below , CR's show up as \r, LF's show up as \n, and 
each line starts with S or C depending upon whether it is from the 
Server or Client.  There is blank line following each connection.

Thanks,
Ron

============================================================================
S * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE I
S DLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.\r\n
C 10001 LOGIN testimap at usgo.net ***********\r\n
S 10001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENAB
S LE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDS
S UBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UID
S PLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRE
S S WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
S \r\n
C 10002 STATUS INBOX (MESSAGES UNSEEN)\r\n
S * STATUS INBOX (MESSAGES 3 UNSEEN 3)\r\n
S 10002 OK Status completed.\r\n
C 10003 SELECT INBOX\r\n
S * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)\r\n
S * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*
S )] Flags permitted.\r\n
S * 3 EXISTS\r\n
S * 1 RECENT\r\n
S * OK [UNSEEN 1] First unseen.\r\n
S * OK [UIDVALIDITY 1457030049] UIDs valid\r\n
S * OK [UIDNEXT 129] Predicted next UID\r\n
S * OK [HIGHESTMODSEQ 417] Highest\r\n
S 10003 OK [READ-WRITE] Select completed (0.000 secs).\r\n
C 10004 UID SEARCH 3\r\n
S * SEARCH 128\r\n
S 10004 OK Search completed (0.000 secs).\r\n
C 10005 LIST "" Trash\r\n
S * LIST (\HasNoChildren \Trash) "." Trash\r\n
S 10005 OK List completed.\r\n
C 10006 UID STORE 128 +FLAGS.SILENT (\Seen)\r\n
S 10006 OK Store completed.\r\n
C 10007 UID MOVE 128 Trash\r\n
S * OK [COPYUID 1457030331 128 127] Moved UIDs.\r\n
S * 3 EXPUNGE\r\n
S * 0 RECENT\r\n
S 10007 OK Move completed.\r\n
C 10008 STATUS INBOX (MESSAGES UNSEEN)\r\n
S * STATUS INBOX (MESSAGES 2 UNSEEN 2)\r\n
S 10008 OK [CLIENTBUG] Status on selected mailbox completed.\r\n
C 10009 STATUS Trash (MESSAGES UNSEEN)\r\n
S * STATUS Trash (MESSAGES 1 UNSEEN 0)\r\n
S 10009 OK Status completed.\r\n
C 10010 LOGOUT\r\n
S * BYE Logging out\r\n
S 10010 OK Logout completed.\r\n

S * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE I
S DLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.\r\n
C 10001 LOGIN testimap at usgo.net ***********\r\n
S 10001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENAB
S LE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDS
S UBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UID
S PLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRE
S S WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
S \r\n
C 10002 SELECT INBOX\r\n
S * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)\r\n
S * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*
S )] Flags permitted.\r\n
S * 2 EXISTS\r\n
S * 0 RECENT\r\n
S * OK [UNSEEN 1] First unseen.\r\n
S * OK [UIDVALIDITY 1457030049] UIDs valid\r\n
S * OK [UIDNEXT 129] Predicted next UID\r\n
S * OK [HIGHESTMODSEQ 419] Highest\r\n
S 10002 OK [READ-WRITE] Select completed (0.026 secs).\r\n
C 10003 UID FETCH 127 (UID RFC822.SIZE FLAGS INTERNALDATE BODYSTRUCTURE B
C ODY.PEEK[HEADER.FIELDS (DATE FROM TO SUBJECT CONTENT-TYPE CC REPLY-TO L
C IST-POST DISPOSITION-NOTIFICATION-TO X-PRIORITY IN-REPLY-TO BCC SENDER
C MESSAGE-ID CONTENT-TRANSFER-ENCODING REFERENCES X-DRAFT-INFO MAIL-FOLLO
C WUP-TO MAIL-REPLY-TO RETURN-PATH)])\r\n
S * 2 FETCH (UID 127 RFC822.SIZE 771 FLAGS () INTERNALDATE "08-Mar-2016 0
S 8:48:31 -0600" BODYSTRUCTURE ("text" "plain" ("charset" "us-ascii") NIL
S  NIL "7bit" 7 1 NIL NIL NIL NIL) BODY[HEADER.FIELDS (DATE FROM TO SUBJE
S CT CONTENT-TYPE CC REPLY-TO LIST-POST DISPOSITION-NOTIFICATION-TO X-PRI
S ORITY IN-REPLY-TO BCC SENDER MESSAGE-ID CONTENT-TRANSFER-ENCODING REFER
S ENCES X-DRAFT-INFO MAIL-FOLLOWUP-TO MAIL-REPLY-TO RETURN-PATH)] {108}\r
S \n
S From: ron at cleven.com\r\n
S To: testimap at usgo.net\r\n
S Date: Tue, 08 Mar 2016 08:48:24 -0600 (CST)\r\n
S Subject: test2\r\n
S \r\n
S )\r\n
S 10003 OK Fetch completed.\r\n
C 10004 UID FETCH 127 (BODY.PEEK[TEXT])\r\n
S * 2 FETCH (UID 127 BODY[TEXT] {7}\r\n
S test2\r\n
S )\r\n
S 10004 OK Fetch completed.\r\n
C 10005 UID STORE 127 +FLAGS.SILENT (\Seen)\r\n
S 10005 OK Store completed.\r\n
C 10006 LOGOUT\r\n
S * BYE Logging out\r\n
S 10006 OK Logout completed.\r\n

S * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE I
S DLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.\r\n
C 10001 LOGIN testimap at usgo.net ***********\r\n
S 10001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENAB
S LE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDS
S UBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UID
S PLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRE
S S WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
S \r\n
C 10002 LIST (SUBSCRIBED) "" "*"\r\n
S * LIST (\Subscribed) "." Sent\r\n
S * LIST (\Subscribed) "." Trash\r\n
S * LIST (\Subscribed) "." Drafts\r\n
S * LIST (\Subscribed) "." Junk\r\n
S * LIST (\Subscribed) "." Blocked\r\n
S * LIST (\Subscribed) "." Pending\r\n
S * LIST (\Subscribed) "." Archives\r\n
S * LIST (\Subscribed) "." Archives.2016\r\n
S 10002 OK List completed.\r\n
C 10003 STATUS INBOX (MESSAGES UNSEEN)\r\n
S * STATUS INBOX (MESSAGES 2 UNSEEN 1)\r\n
S 10003 OK Status completed.\r\n
C 10004 LOGOUT\r\n
S * BYE Logging out\r\n
S 10004 OK Logout completed.\r\n

S * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE I
S DLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.\r\n
C 10001 LOGIN testimap at usgo.net ***********\r\n
S 10001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENAB
S LE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDS
S UBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UID
S PLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRE
S S WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
S \r\n
C 10002 LIST (SUBSCRIBED) "" "*"\r\n
S * LIST (\Subscribed) "." Sent\r\n
S * LIST (\Subscribed) "." Trash\r\n
S * LIST (\Subscribed) "." Drafts\r\n
S * LIST (\Subscribed) "." Junk\r\n
S * LIST (\Subscribed) "." Blocked\r\n
S * LIST (\Subscribed) "." Pending\r\n
S * LIST (\Subscribed) "." Archives\r\n
S * LIST (\Subscribed) "." Archives.2016\r\n
S 10002 OK List completed.\r\n
C 10003 STATUS INBOX (MESSAGES UNSEEN)\r\n
S * STATUS INBOX (MESSAGES 3 UNSEEN 2)\r\n
S 10003 OK Status completed.\r\n
C 10004 LOGOUT\r\n
S * BYE Logging out\r\n
S 10004 OK Logout completed.\r\n
============================================================================