[Dovecot] mbox sync: Expunged message reappeared in mailbox
Starting at 05:32 this morning, one user on my dovecot server is receiving hundreds of copies of old email. This is a short excerpt from my dovecot.log showing the problem:
dovecot: Nov 03 05:27:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:27:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 05:32:01 Error: POP3(joyce@obfusca.ted): mbox sync: Expunged message reappeared in mailbox /var/mail/vhosts/obfusca.ted/joyce (UID 1443 < 1446, seq=2, idx_msgs=0) dovecot: Nov 03 05:32:01 Info: pop3-login: Login: user=joyce@obfusca.ted, method=PLAIN, rip=::ffff:67.9.149.201, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:32:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:32:03 Info: POP3(joyce@obfusca.ted): Disconnected: Logged out top=0/0, retr=3/163473, del=3/3, size=163419 dovecot: Nov 03 05:32:03 Error: POP3(joyce@obfusca.ted): mbox sync: Expunged message reappeared in mailbox /var/mail/vhosts/obfusca.ted/joyce (UID 1443 < 1449, seq=2, idx_msgs=0) dovecot: Nov 03 05:32:03 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 05:37:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:37:03 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/3, size=0 dovecot: Nov 03 05:42:01 Info: pop3-login: Login: user=joyce@obfusca.ted, method=PLAIN, rip=::ffff:67.9.149.201, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:42:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:42:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 05:42:03 Info: POP3(joyce@obfusca.ted): Disconnected: Logged out top=0/0, retr=3/163461, del=3/3, size=0 dovecot: Nov 03 05:47:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:47:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 05:52:01 Error: POP3(joyce@obfusca.ted): mbox sync: Expunged message reappeared in mailbox /var/mail/vhosts/obfusca.ted/joyce (UID 1449 < 1452, seq=2, idx_msgs=0) dovecot: Nov 03 05:52:01 Info: pop3-login: Login: user=joyce@obfusca.ted, method=PLAIN, rip=::ffff:67.9.149.201, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:52:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:52:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 05:52:03 Info: POP3(joyce@obfusca.ted): Disconnected: Logged out top=0/0, retr=3/163473, del=3/3, size=163419 dovecot: Nov 03 05:52:03 Error: POP3(joyce@obfusca.ted): mbox sync: Expunged message reappeared in mailbox /var/mail/vhosts/obfusca.ted/joyce (UID 1449 < 1455, seq=2, idx_msgs=0) dovecot: Nov 03 05:57:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 05:57:03 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/3, size=0 dovecot: Nov 03 06:02:01 Info: pop3-login: Login: user=joyce@obfusca.ted, method=PLAIN, rip=::ffff:67.9.149.201, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 06:02:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 06:02:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 06:02:02 Info: POP3(joyce@obfusca.ted): Disconnected: Logged out top=0/0, retr=3/163461, del=3/3, size=0 dovecot: Nov 03 06:07:02 Info: pop3-login: Login: user=howard@obfusca.ted, method=PLAIN, rip=::ffff:81.44.31.210, lip=::ffff:zz.zz.zz.zz, TLS dovecot: Nov 03 06:07:02 Info: POP3(howard@obfusca.ted): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 dovecot: Nov 03 06:12:01 Error: POP3(joyce@obfusca.ted): mbox sync: Expunged message reappeared in mailbox /var/mail/vhosts/obfusca.ted/joyce (UID 1455 < 1458, seq=2, idx_msgs=0)
Dovecot version:
[jhg@helios ~]$ rpm -q dovecot dovecot-1.0-0.beta8.2.fc5
The MTA is postfix, and this is the first time this has ever happened.
I made a copy of the mbox file, and find that it's over a megabyte long. Checking the postfix maillog I find that only three messages arrived for that user in the hour preceding the start of this behavior (all SPAM).
No other users are affected, and I can't see anything obviously wrong in the mbox file. Could a bad message cause this?
I just saw this message also:
dovecot: Nov 03 10:35:59 Error: POP3(joyce@jhmg.net): mbox sync: UID inserted in the middle of mailbox /var/mail/vhosts/jhmg.net/joyce (1603 > 1595, seq=2, idx_msgs=9) Does (1603 > 1595) refer to line numbers in the file?
Jim Garrison wrote:
Starting at 05:32 this morning, one user on my dovecot server is receiving hundreds of copies of old email. This is a short excerpt from my dovecot.log showing the problem:
[snip]
On Fri, 2006-11-03 at 12:55 -0600, Jim Garrison wrote:
I just saw this message also:
dovecot: Nov 03 10:35:59 Error: POP3(joyce@jhmg.net): mbox sync: UID inserted in the middle of mailbox /var/mail/vhosts/jhmg.net/joyce (1603 > 1595, seq=2, idx_msgs=9) Does (1603 > 1595) refer to line numbers in the file?
They refer to messages' UIDs. The above message means that the second mail in the mbox file contained "X-UID: 1595" header, while the mbox had already contained UIDs up to 1603.
This by itself isn't enough to give the error though. If Dovecot sees broken X-UID headers for "new" messages, they're silently fixed. So besides having a broken X-UID header, Dovecot had to think this was a message it had already seen. In the above message it says Dovecot last saw 9 messages in the mbox file, and it's now parsing only the second one. So it means that something expunged the messages outside Dovecot.
So.. If the mboxes are changed only using Dovecot, this really shouldn't be happening. Typically it could only happen when eg. copying an older backup of the mbox file over the new changed one.
Jim Garrison wrote:
Starting at 05:32 this morning, one user on my dovecot server is receiving hundreds of copies of old email. This is a short excerpt from my dovecot.log showing the problem:
You should anyway filter out the X-UID headers (and preferrably other Dovecot's metadata headers) in your MTA/LDA so that they won't get written to the mbox. That might help here if mbox is modified externally also.
Anyway, these error messages shouldn't show up to users in any way. They get automatically fixed and won't give the client any error messages.
participants (2)
-
Jim Garrison
-
Timo Sirainen