Jim Garrison
2006-Nov-03 18:42 UTC
[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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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?
Jim Garrison
2006-Nov-03 18:55 UTC
[Dovecot] mbox sync: Expunged message reappeared in mailbox
I just saw this message also:> dovecot: Nov 03 10:35:59 Error: POP3(joyce at 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]