Reappearing emails - IMAP trace
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 TrashIf 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@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@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@cleven.com\r\n S To: testimap@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@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@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
On 09 Mar 2016, at 03:57, Ron Cleven Ron@Cleven.com wrote:
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.
What mailbox format do you use? Are you able to reproduce this by running doveadm sync commands manually instead of letting replication do it? For example:
- doveadm sync -s "" -d -u user@domain > state
- Run the UID STORE & UID MOVE
- doveadm sync -s "
cat state" -d -u user@domain
There have been some fixes, especially recently https://github.com/dovecot/core/commit/950a6e61d6c2dac961ce031bdd8b2895bc32b... sounds a bit similar although I don't really see how it would apply here. Would be a good idea to try anyway with v2.2.22.rc1 (which seems to be stable enough that I'll make v2.2.22 release soon).
Anyway, I attempted a few times to reproduce it with your test but wasn't able to.
participants (2)
-
Ron Cleven
-
Timo Sirainen