[Dovecot] mbox sync: Expunged message reappeared in mailbox

[Jim Garrison]

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?