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

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 =

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@cuci.nl Copyright (c) 1997-2001, Philip A. Guenther guenther@sendmail.com

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

And of course, subscription and information requests for this list to: procmail-users-request@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.