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(a)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(a)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(a)cleven.com\r\n
S To: testimap(a)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(a)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(a)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
============================================================================