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

Thu Apr 16 06:56:54 UTC 2015

-----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.

> 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.

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'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: " ...

> 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?

> 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-----