[Dovecot] Expunged message reappeared, giving a new UID

[Simon Fraser]

On Thu, 2013-08-01 at 15:09 +0300, Timo Sirainen wrote:
> On Fri, 2013-07-26 at 11:28 +0100, Simon Fraser wrote:
> 
> > I am running dovecot 2.2.2 with tcp based replication, and experiencing
> > some duplicated emails. `doveconf -n` output is below.
> 
> Are both of the servers using the same mailbox format?

Yes, they are. `doveconf -n | grep mail_location` on both nodes gives:
mail_location = maildir:~/mail:INBOX=~/mail/INBOX

I've also tried with mdbox.

> > Connect with a mail client, and delete the message - without delayed
> > expunge. So, for example, mutt (press 'd' then '$' to sync the mailbox),
> > or Evolution set to immediately delete.
> 
> Can you reproduce this by disabling automatic replication (e.g. just
> remove replicator from mail_plugins) and running dsync manually? So
> basically delete the message, then run:
> 
> doveadm sync -r rawlog -u user at domain -d
> 
> If that reproduces it, send the rawlog to me.

I can't reproduce it with that, sorry. Message deletion appears to work
that way, and the command only produces I/O leak errors:

dsync-local(srf at sanger.ac.uk): Warning: I/O leak: 0x7f00e50cc960 (line
341, fd 9)

Using mail delivery and imap connections to node 'a' only, I have tried:

1) mail delivered, connecting/deleting/expunging, then sync
2) mail delivered, syncing, connecting/deleting/expunging, not syncing,
then checking
3) mail delivered, syncing, connecting/deleting/expunging, syncing

None cause the message to reappear. I tried initiating the sync from
both nodes, just in case. 

Leaving the replication plugin enabled causes it to happen, though, so
perhaps my timing is off.

Other things I have discovered by running 'watch' or a while loop, both
grepping the mail_location for my test subject line:

A message is visible over imap before being written to mail_location. If
I can manage to delete it in this time (there isn't much time!) then the
message does not reappear.

When the message reappears it gets a different filename (please excuse
the grep output on the end):
cur/1375364237.M969208P14576.intmail3a,S=2672,W=2731:2,:Subject: dup
test

is replaced with:
cur/1375364242.M782761P838.intmail3b,S=2672,W=2731:2,:Subject: dup test

This occurs less than a second after the expunge. There's only a log
entry on intmail3a, not 3b:

Aug  1 14:37:26 intmail3a dovecot: imap(srf):
Warning: /mail/spool/s/srf/mail/INBOX/dovecot-uidlist: Duplicate file
entry at line 105: 1375364237.M969208P14576.intmail3a,S=2672,W=2731 (uid
772051 -> 772052)

I'm happy to run as many diagnostics as required, just let me know what
you'd like.

Simon.




-- 
 The Wellcome Trust Sanger Institute is operated by Genome Research 
 Limited, a charity registered in England with number 1021457 and a 
 company registered in England with number 2742969, whose registered 
 office is 215 Euston Road, London, NW1 2BE.