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?