Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads

Thu Apr 16 14:13:08 UTC 2015

Steffen,

Thank you very much for your help.  It is very much appreciated.

--On Thursday, April 16, 2015 08:56 +0200 Steffen Kaiser 
<skdovecot at smail.inf.fh-brs.de> wrote:

> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On Thu, 16 Apr 2015, David Gessel wrote:
>
>> My Dovecot 2.2.16 server is interacting poorly with a variety of mail
>> clients.  The symptoms include disappearing messages, mismatched
>> summaries,  duplicated messages, and excessive full re-downloads.
>>
>> Dovecot 2.2.16 on FreeBSD 10.1-release r280247M ZFS is interacting
>> suboptimally with various email clients.  Output of "dovecot -n" further
>> down.
>
> ZFS does have some features, that allow backups and restore and such, if
> I remember correctly.

ZFS can do some awesome things like snapshotting and the like, but they're 
hidden from the OS  (no atime modification if that is enabled, for example) 
and you can exchange your disks for larger ones and expand into the new 
space with a single command.

It is possible there is an unexpected interaction between ZFS and Maildir, 
but a good friend of mine runs Dovecot/Maildir on a BSD 10.0/ZFS system 
without the issues I'm seeing.  I've created a diff of our dovecot -n 
outputs that I'd be happy to share, but it is a styled HTML file and 
attachments are usually mailing list unfriendly.

The documentation at <http://wiki2.dovecot.org/MailboxFormat/Maildir> 
suggests that file system level issues are mostly about performance.

This note seems aprops:

"Locking

"Although maildir was designed to be lockless, Dovecot locks the maildir 
while doing modifications to it or while looking for new messages in it. 
This is required because otherwise Dovecot might temporarily see mails 
incorrectly deleted, which would cause trouble. Basically the problem is 
that if one process modifies the maildir (eg. a rename() to change a 
message's flag), another process in the middle of listing files at the same 
time could skip a file. The skipping happens because readdir() system call 
doesn't guarantee that all the files are returned if the directory is 
modified between the calls to it. This problem exists with all the commonly 
used filesystems.

"Because Dovecot uses its own non-standard locking (dovecot-uidlist.lock 
dotlock file), other MUAs accessing the maildir don't support it. This 
means that if another MUA is updating messages' flags or expunging 
messages, Dovecot might temporarily lose some message. After the next sync 
when it finds it again, *an error message may be written to log and the 
message will receive a new UID.*

"Delivering mails to new/ directory doesn't have any problems, so there's 
no need for LDAs to support any type of locking."

(emphasis added)

Certainly flags are not being set on 1000's of messages at a time and while 
I tend to suspect Thunderbird of doing things that are flaky or out of spec 
in an attempt to be clever and efficient, Mulberry tends to be painfully 
strictly adherent to specification.

>
>> dovecot.log shows runs of this error:
>> Apr 15 09:02:37 imap(user at domain.com): Warning: Maildir
>> /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new
>> UID  (old uid=306286,
>> file=1429102024.M826331P1156.host,S=1678,W=1724:2,S)
>
> Such message I saw only, when I manually changed files in the Maildir
> directory. That's why I pointed out ZFS above. Do you use some
> strategies, that freezes a Maildir, then do something (e.g. backup), then
> thaw the Maildir. During the backup, a client could delete a message,
> which reapper after thaw.

Understood and agreed - it seems like some process is moving things around, 
but there's no file-system level indication that is happening.  In fact, 
watching the logs live, these messages flood the log whenever a message is 
sent (sending this message will trigger an avalanche of "expunged message 
reappeared" messages, for example).

>
> Other possibilities: rsync/copy, vi, ... on file system level
> When you operate on filesystem level on the Maildirs keep in mind, that
> filenames store message flags and status, which may change regularily.
>

I do nightly RSYNC backups to a FreeNAS server from the host (mail runs 
from a freebsd jail), but the updates are far, far more frequent than those 
daily backups.

>> I've set
>> mbox_dirty_syncs = no
>> mbox_lazy_writes = no
>
> you are using Maildir, no? They don't effect Maildir.
>
>> mail_location = maildir:~:CONTROL=/var/no-quota/%u
>
> this one hits me:
>
> http://wiki2.dovecot.org/VirtualUsers/Home
> "Home directory shouldn't be the same as mail directory. It's possible to
> do that, but you might run into trouble with it sooner or later. Some
> problems with this are: " ...

That makes sense, but this directory structure does not put the mail in the 
user's home directory.  It is a directory that nothing but the mail system 
touches (normally, unless I'm poking around looking for problems).  The 
home directories are in their usual places: /usr/home/user...  and have no 
(active) Maildir.

Mail is under an entirely separate root level directory: 
/mail/domain.tld/user...

>
>> mail_plugins = quota mail_log notify fts fts_lucene
>
> I don't run FTS, where does lucene store its files? In the user's home?

Within the maildir, so the FTS_lucene indicies are at

/mail/domain.tld/user/lucene-indexes/_8u.cfs
/mail/domain.tld/user/lucene-indexes/segements.gen
/mail/domain.tld/user/lucene-indexes/segements_hr

Frankly, FTS is a little disappointing.  Stand-alone clients don't support 
server-side search well, in particular they seem to limit search to the 
active folder rather than searching across the entire mailbox.  The premise 
of FTS for me was to enable particularly mobile devices (=K9/Android) to 
have search access to the entire mailbox and all archives in some 
relatively expedient fashion since there are not yet uSD cards large enough 
to store all that mail.  But no...  it doesn't really seem to work that 
way.  You can find a message within the currently active folder quickly, 
but you can do that without server-side search anyway.

Mulberry does a pretty amazing job of this, however.  You can watch it 
blast through directories that have FTS indexing one after another.

>
>> Apr 15 13:17:26 indexer-worker(user at domain.com):
>> user-lookup(user at domain.com)Debug: Added userdb setting: mail=maildir:~/
>> Apr 15 13:17:26 indexer-worker(user at domain.com):
>> user-lookup(user at domain.com)Debug: Added userdb setting:
>> plugin/quota_rule=*:bytes=0
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Effective
>> uid=5000,  gid=5000, home=/mail/domain.com/user/
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota root:
>> name=User  quota backend=maildir args=
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota rule:
>> root=User  quota mailbox=* bytes=0 messages=0
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota rule:
>> root=User  quota mailbox=Trash bytes=0 (30%) messages=0
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota rule:
>> root=User  quota mailbox=Sent bytes=0 (30%) messages=0
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota warning:
>> bytes=0 (90%) messages=0 reverse=no command=quota-warning 90
>> user at domain.com Apr 15 13:17:26 indexer-worker(user at domain.com): Debug:
>> Quota warning:  bytes=0 (75%) messages=0 reverse=no
>> command=quota-warning 75 user at domain.com Apr 15 13:17:26
>> indexer-worker(user at domain.com): Debug: Quota grace:  root=User quota
>> bytes=0 (10%)
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Namespace inbox:
>> type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes,
>> subscriptions=yes location=maildir:~/
>> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: maildir++:
>> root=/mail/domain.com/user/, index=, indexpvt=, control=,
>> inbox=/mail/domain.com/user/, alt=
>> Apr 15 13:17:27 indexer-worker(user at domain.com): Debug: Ignoring unknown
>> cache field: pop3.order
>> Apr 15 13:17:27 indexer-worker(user at domain.com): Debug: Ignoring unknown
>> cache field: binary.parts
>> Apr 15 13:17:27 indexer-worker(user at domain.com): Debug: Ignoring unknown
>> cache field: body.snippet
>>
>>
>> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota root: name=User quota
>> backend=maildir args=
>> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=* bytes=53687091200 messages=0
>> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=Trash bytes=+16106127360 (30%) messages=0
>> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=Sent bytes=+16106127360 (30%) messages=0
>> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota warning:
>> bytes=48318382080  (90%) messages=0 reverse=no command=quota-warning 90
>> raw mail user Apr 15 13:44:25 lda(user at domain.com): Debug: Quota
>> warning: bytes=40265318400  (75%) messages=0 reverse=no
>> command=quota-warning 75 raw mail user Apr 15 13:44:25
>> lda(user at domain.com): Debug: Quota grace: root=User quota
>> bytes=5368709120 (10%)
>> Apr 15 13:44:25 lda(user at domain.com): Debug: none: root=, index=,
>> indexpvt=,  control=, inbox=, alt=
>> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota root: name=User quota
>> backend=maildir args=
>> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=* bytes=53687091200 messages=0
>> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=Trash bytes=+16106127360 (30%) messages=0
>> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=Sent bytes=+16106127360 (30%) messages=0
>> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota warning:
>> bytes=48318382080  (90%) messages=0 reverse=no command=quota-warning 90
>> raw mail user Apr 15 13:49:32 lda(user at domain.com): Debug: Quota
>> warning: bytes=40265318400  (75%) messages=0 reverse=no
>> command=quota-warning 75 raw mail user Apr 15 13:49:32
>> lda(user at domain.com): Debug: Quota grace: root=User quota
>> bytes=5368709120 (10%)
>> Apr 15 13:49:32 lda(user at domain.com): Debug: none: root=, index=,
>> indexpvt=,  control=, inbox=, alt=
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file storage: Using
>> script storage path: /mail/domain.com/user//sieve
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file storage:
>> Relative  path to sieve storage in active link: sieve/
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `Forwards' from `/mail/domain.com/user/sieve/Forwards.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Server_Msg' from
>> `/mail/domain.com/user/sieve/File_Server_Msg.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_SRL' from `/mail/domain.com/user/sieve/File_SRL.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_BULK' from `/mail/domain.com/user/sieve/File_BULK.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Commerce' from
>> `/mail/domain.com/user/sieve/File_Commerce.sieve' Apr 15 13:49:41
>> lda(user at domain.com): Debug: sieve: file script: Opened  script
>> `File_Impersonal' from
>> `/mail/domain.com/user/sieve/File_Impersonal.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Travel' from `/mail/domain.com/user/sieve/File_Travel.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Tribe' from `/mail/domain.com/user/sieve/File_Tribe.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Info' from `/mail/domain.com/user/sieve/File_Info.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Lists' from `/mail/domain.com/user/sieve/File_Lists.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Trash' from `/mail/domain.com/user/sieve/File_Trash.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Security' from
>> `/mail/domain.com/user/sieve/File_Security.sieve' Apr 15 13:49:41
>> lda(user at domain.com): Debug: sieve: file script: Opened  script
>> `File_Notifications' from
>> `/mail/domain.com/user/sieve/File_Notifications.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened
>> script `File_Spam' from `/mail/domain.com/user/sieve/File_Spam.sieve'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: Script binary
>> /mail/domain.com/user/.dovecot.svbin successfully loaded
>> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: binary save: not
>> saving  binary /mail/domain.com/user/.dovecot.svbin, because it is
>> already stored Apr 15 13:49:41 lda(user at domain.com): Debug: sieve:
>> Executing script from  `/mail/domain.com/user/.dovecot.svbin'
>> Apr 15 13:49:41 lda(user at domain.com): Debug: Quota root: name=User quota
>> backend=maildir args=
>> Apr 15 13:49:41 lda(user at domain.com): Debug: Quota rule: root=User quota
>> mailbox=* bytes=53687091200 messages=0
>>
>>
>>
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Loading modules from
>> directory:  /usr/local/lib/dovecot
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib10_quota_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib11_imap_quota_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib15_notify_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib20_fts_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib20_mail_log_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded:
>> /usr/local/lib/dovecot/lib21_fts_lucene_plugin.so
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Added userdb setting:
>> plugin/quota_rule=*:bytes=0
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Effective uid=5000,
>> gid=5000,  home=/mail/domain.com/user/
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota root: name=User
>> quota  backend=maildir args=
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota rule: root=User
>> quota  mailbox=* bytes=0 messages=0
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota rule: root=User
>> quota  mailbox=Trash bytes=0 (30%) messages=0
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota rule: root=User
>> quota  mailbox=Sent bytes=0 (30%) messages=0
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota warning: bytes=0
>> (90%)  messages=0 reverse=no command=quota-warning 90 user at domain.com
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota warning: bytes=0
>> (75%)  messages=0 reverse=no command=quota-warning 75 user at domain.com
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota grace: root=User
>> quota  bytes=0 (10%)
>> Apr 15 13:30:31 imap(user at domain.com): Debug: Namespace inbox:
>> type=private,  prefix=, sep=, inbox=yes, hidden=no, list=yes,
>> subscriptions=yes
>> location=maildir:~:CONTROL=/var/no-quota/user at domain.com
>> Apr 15 13:30:31 imap(user at domain.com): Debug: maildir++:
>> root=/mail/domain.com/user/, index=, indexpvt=,
>> control=/var/no-quota/user at domain.com, inbox=/mail/domain.com/user/, alt=
>>
>
> - -- Steffen Kaiser
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
>
> iQEVAwUBVS9dNnz1H7kL/d9rAQLn8Af/cQ8BSg6cmUFj6qGVcQUglJkI8hjY3CQM
> 2MBI/qQbouo4hg3eQNOLX+MOYAGcCV2I+wM8WkOJkqOjPn8vBZACHe5Y860mBbEA
> XipvGMML1DJt+4leNo/1jPpiFJEFZ3w9kFiCC+rPcjrTU8XV5g+l9RQDofu8vElZ
> jySGQvH3Ml7kP2afTrqiBb3cwoQVLXMYUTsjw4csw0qn3lWB7i3yN/WACsBMFBP6
> H0KnM99UUYbOJ4TMsBJ7aDXIUIvlu6Eo1oGznIsKiX1k6BoCPQtXwlxk4NJ6f8B/
> SaGYf6FPSQmKaePTVwxJfSc8sTBxb+rG7DsZQnGjwZFtGH3ti810eg==
> =6hFs
> -----END PGP SIGNATURE-----