[Dovecot] Getting duplicates despite trying hard to match lock styles

[Richard Walker]

I'm attempting to replace (a) a very old setup that has POP (qpopper)
access to inboxes and a separate UW IMAP server that provides folders,
with (b) a shiny new mail setup with dovecot providing both inboxes
and IMAP support.

For the new mail server I created a virtual machine running a minimal
Fedora 16 installation and installed sendmail, MIMEDefang,
SpamAssassin, ClamAV, procmail, and dovecot.  I have kept installing
updates as they become available.

For now I'm running the old and new mail setups in parallel; I have
configured the original sendmail server to forward copies of incoming
messages to the new sendmail running on the virtual machine.  I then
compare the results (e.g., how spam filtering is working).

I've kept as much as possible of the original _style_ of setup as
possible, which in particular means using sendmail, and message
delivery through procmail to mbox files in /var/spool/mail.  The key
difference is the use of dovecot to provide IMAP access to the inbox
and IMAP folders.

Because of the legacy setup, my desktop access to email is via
Thunderbird 2.0.0.22 on a very old Mac PowerBook G4 to work with both
old and new setups and I have two windows open to make comparison
possible.  (Yes, both mail servers are on separate computers, not on
this notebook.)

Mostly this is working fine (after a fair bit of tweaking, including
adding custom SELinux rules to get rid of all AVCs).  I put the
notebook to sleep overnight, and in the morning I open it up and see
what happens.  After a few minutes, the window with the old setup does
its POP fetch; the window with the new setup almost straightaway shows
the new messages in its version of the inbox.

Not quite: again, for legacy reasons I have some Thunderbird filters,
and I have duplicated those (still within Thunderbird) for the new
setup.  The filters are:
1. Move messages tagged as spam by SpamAssassin to the Junk folder.
2. Move messages from GeoNetwork-related senders to a "GeoNetwork"
   folder.
3. Move all remaining messages to the "In" folder.

Most mornings this works just fine.  But not always.  Sometimes I get
duplicates in the "In" and "GeoNetwork" folders of the new
dovecot-based setup.  I used to get _garbled_ duplicates (with extra
random bits of other messages at the end of the duplicates) in the new
setup, which I presumed must be due to a locking configuration
mismatch.  Having fixed that (see below) I no longer get garbled
duplicates, but I do still sometimes (including today) get identical
duplicates.  This seems to happen when one of the incoming messages
has a very large attachment - but you may wish to treat that as
hearsay.

I attach below:
0. The line from /etc/mtab on the new server that covers the
   filesystem (i.e., including /var/spool and /home).
1. Output of "doveconf -n" and a note about how I modified locking
   from the Fedora default.
2. Output of "procmail -v".
3. Sendmail procmail mailer config (for good measure; I don't think
   you need this).
4. An excerpt from /var/log/maillog on the new server showing the
   beginning of dovecot processing this morning when I opened my
   notebook.
5. A link to the dovecot raw log files of my "INBOX" and "In" folder
   processing from this morning.

You'll see from the dovecot log files that Thunderbird sends expunge
commands, but the expunged messages hang around -- indeed, the same
messages get expunged several times!  And eventually they get fetched
again -- hence the duplicates I see in Thunderbird.

Given that INBOX.out contains:

08:56:53.765423 * 537 EXISTS
08:56:53.765423 * 533 RECENT

and then, after many expunges:

08:56:58.441341 * 16 EXPUNGE
08:56:58.441341 * 11 EXPUNGE
08:56:58.441341 * 3 EXPUNGE
08:56:58.441341 * 539 EXISTS
08:56:58.441341 * 536 RECENT
08:56:58.441341 9 OK Expunge completed.

it looks like I still have a locking problem.  I have tried very hard
to understand the locking options in dovecot.conf and to match dovecot
with procmail -- apparently, there is more to do.


0. The line from /etc/mtab for the filesystem:

----------
/dev/mapper/vg_f16i386serverbasic-lv_root / ext4
rw,seclabel,relatime,user_xattr,acl,barrier=1,data=ordered 0 0
----------


1. doveconf -n says:

----------
# 2.0.20: /etc/dovecot/dovecot.conf
# OS: Linux 3.3.6-3.fc16.i686.PAE i686 Fedora release 16 (Verne)
mail_debug = yes
mail_privileged_group = mail
namespace {
  hidden = yes
  inbox = yes
  list = no
  location = mbox:~/mail:INBOX=/var/spool/mail/%u
  prefix = "#mbox/"
  separator = /
  type = private
}
namespace {
  inbox = no
  location = maildir:~/Maildir
  prefix =
  separator = /
  type = private
}
passdb {
  driver = pam
}
service imap-login {
  inet_listener imap {
    address = localhost
  }
}
service imap {
  executable = imap postlogin
}
service pop3-login {
  inet_listener pop3 {
    address = localhost
  }
}
service postlogin {
  executable = script-login -d rawlog -t
}
ssl_cert = </etc/pki/dovecot/certs/dovecot.pem
ssl_key = </etc/pki/dovecot/private/dovecot.pem
userdb {
  driver = passwd
}
----------

Note that the default Fedora installation specifies:

  mbox_write_locks = fcntl

and I commented that out.  This seems  to restore the default setting of:

  mbox_write_locks = dotlock fcntl

to match procmail.


2. procmail -v (run as me) says:

----------
procmail v3.22 2001/09/10
    Copyright (c) 1990-2001, Stephen R. van den Berg    <srb at cuci.nl>
    Copyright (c) 1997-2001, Philip A. Guenther         <guenther at sendmail.com>

Submit questions/answers to the procmail-related mailinglist by sending to:
        <procmail-users at procmail.org>

And of course, subscription and information requests for this list to:
        <procmail-users-request at procmail.org>

Locking strategies:     dotlocking, fcntl()
Default rcfile:         $HOME/.procmailrc
        It may be writable by your primary group
Your system mailbox:    /var/spool/mail/rw
----------

(There is no $HOME/.procmailrc or other system-wide procmailrc.)

3. The mailer as defined in sendmail.cf says:

----------
Mlocal,         P=/usr/bin/procmail, F=lsDFMAw5:/|@qSPfhn9,
S=EnvFromL/HdrFromL, R=EnvToL/HdrToL,
                T=DNS/RFC822/X-Unix,
                A=procmail -t -Y -a $h -d $u
----------

4. The relevant lines from /var/log/maillog:

----------
Jun 12 08:56:53 localhost dovecot: imap-login: Login: user=<rw>,
method=PLAIN, rip=192.168.2.200, lip=192.168.2.188, mpid=21618, TLS
Jun 12 08:56:53 localhost dovecot: imap(rw): Debug: Effective
uid=1000, gid=100, home=/home/rw
Jun 12 08:56:53 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=#mbox/, sep=/, inbox=yes, hidden=yes, list=no,
subscriptions=yes location=mbox:~/mail:INBOX=/var/spool/mail/rw
Jun 12 08:56:53 localhost dovecot: imap(rw): Debug: fs:
root=/home/rw/mail, index=, control=, inbox=/var/spool/mail/rw, alt=
Jun 12 08:56:53 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=yes location=maildir:~/Maildir
Jun 12 08:56:53 localhost dovecot: imap(rw): Debug: maildir++:
root=/home/rw/Maildir, index=, control=, inbox=, alt=
Jun 12 08:56:58 localhost dovecot: imap-login: Login: user=<rw>,
method=PLAIN, rip=192.168.2.200, lip=192.168.2.188, mpid=21625, TLS
Jun 12 08:56:58 localhost dovecot: imap(rw): Debug: Effective
uid=1000, gid=100, home=/home/rw
Jun 12 08:56:58 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=#mbox/, sep=/, inbox=yes, hidden=yes, list=no,
subscriptions=yes location=mbox:~/mail:INBOX=/var/spool/mail/rw
Jun 12 08:56:58 localhost dovecot: imap(rw): Debug: fs:
root=/home/rw/mail, index=, control=, inbox=/var/spool/mail/rw, alt=
Jun 12 08:56:58 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=yes location=maildir:~/Maildir
Jun 12 08:56:58 localhost dovecot: imap(rw): Debug: maildir++:
root=/home/rw/Maildir, index=, control=, inbox=, alt=
Jun 12 08:57:03 localhost dovecot: imap-login: Login: user=<rw>,
method=PLAIN, rip=192.168.2.200, lip=192.168.2.188, mpid=21632, TLS
Jun 12 08:57:03 localhost dovecot: imap(rw): Debug: Effective
uid=1000, gid=100, home=/home/rw
Jun 12 08:57:03 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=#mbox/, sep=/, inbox=yes, hidden=yes, list=no,
subscriptions=yes location=mbox:~/mail:INBOX=/var/spool/mail/rw
Jun 12 08:57:03 localhost dovecot: imap(rw): Debug: fs:
root=/home/rw/mail, index=, control=, inbox=/var/spool/mail/rw, alt=
Jun 12 08:57:03 localhost dovecot: imap(rw): Debug: Namespace :
type=private, prefix=, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=yes location=maildir:~/Maildir
Jun 12 08:57:03 localhost dovecot: imap(rw): Debug: maildir++:
root=/home/rw/Maildir, index=, control=, inbox=, alt=
----------

5. dovecot raw logs for "INBOX" and "In".

Because I have trouble comparing times in epoch format, I've run the
logs through a little filter that replaces the timestamps at the
beginning of each line with a timestamp in HH:MM:SS.nanosecond format
in local time.

I've carefully deleted lots of (what I hope are) lines you don't need
from the logs.  E.g., I deleted the middle section of a block of FETCH
statements, leaving the first few and the last few.  Please let me
know if I deleted too much -- I was trying to be helpful.

And of course I replaced e-mail address/subject lines/etc with
XXXXXXXXXX.

Although the Thunderbird filters are "supposed" to be run in the order
I listed above, it seems that Thunderbird fetches all headers, works
out what messages should be filtered to which folders, and then sends
corresponding IMAP commands that copy the messages to the other
folders in a _different_ order of the filters.  (I.e., the INBOX log
shows copy/store/expunge operations in the order "In", "Junk", then
"GeoNetwork", rather than "Junk", "GeoNetwork", "In".)

I have renamed the in/out log files as
INBOX.in, INBOX.out, In.in, In.out and uploaded them to:

https://sites.google.com/site/rwdownloadssite/dovecot-logs

Thanks in advance to anyone who is willing to take a look and advise
what I need to do.