On Fri, 2008-04-11 at 22:52 -0700, Mark Sapiro wrote:
Apr 8 19:07:20 sbh16 dovecot: pop3-login: Login: user=<xxx>, method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Dovecot read-locks the mbox file here.
Apr 8 19:07:22 sbh16 postfix/local[13745]: D959169046B: to=xxx@example.com>, orig_to=xxx@example.org, relay=local, delay=16, delays=15/0/0/1.1, dsn=2.0.0, status=sent (delivered to mailbox) Apr 8 19:07:22 sbh16 dovecot: POP3(xxx): Disconnected: Logged out top=2/15995, retr=0/0, del=2/2, size=15985
These both happen within the same second, so most likely Postfix correctly waits that Doveocot has finished modifying the mbox file and only then delivers its changes.
Five minutes later when fetchmail comes back, we see
Apr 8 19:12:42 sbh16 dovecot: POP3(xxx): mbox sync: Expunged message reappeared in mailbox /var/spool/mail/xxx (UID 4683 < 4684, seq=2, idx_msgs=0)
seq=2 would indicate that there are now two mails, but there should have been only one now.. I tried this a couple of times myself, but it worked in my tests. I'm using v1.0.13 though, so there's also a chance this has been fixed already.
From now on, as messages are added to the mailbox by Postfix, fetchmail keeps retrieving both old and new messages. i.e. even though dovecot's log says del 1/1 (or del n/n) no messages are actually deleted from the mailbox.
This situation continues until someone accesses the mailbox locally (e.g. via mutt through a local shell) and deletes the old messages.
When this happens, could you put the mbox file through http://dovecot.org/tools/mbox-anonymize.pl and send the result to me, along with dovecot.index and dovecot.index.log files.
Also it seems that dovecot should recover from the 'corrupt' mailbox and fix it rather than just continuing to encounter the same problem.
Yes, it shold.