David Gessel
2015-Apr-16 01:45 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
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. *Client Artifacts* Thunderbird 31.6 Win 7 Ultimate SP1: - messages disappear and reappear with checks somewhat randomly. - Sometimes full re-download of folders is triggered, also seems random - Copies of messages appear, sometimes multiplying with each mail check up to about 5-8 or so of each message. - The summary information in the list pane doesn't match the message headers in the preview pane - quit and restart always cleans it up. - sometimes changing folders cleans it up, but not always - sometimes instigating a manual mail check cleans it up but not always Mulberry 4.08 Win 7 Ultimate SP1: - messages disappear and reappear - full re-scans of entire folders triggered occasionally when changing folders, but not always - message list filled with semi-blank entries (message number, status flags, and dates are listed, but no sender, subject, or body is available). The time stamps do not appear to be correct "date received". - message list fills with duplicates - the last of the set of duplicates, which are not necessarily sequentially numbered, has load-able body text and headers, but the others do not. There may be 3-5 copies, only one of which is the real message. The inbox is sequentially numbered by "message number" (the "natural order of the mailbox") and duplicates have unique numbers. - If there's a deleted message left, the "expunge" button is enabled and this also restores normal mailbox view. - disconnecting and reconnecting usually fixes the issues - changing mailboxes while connected sometimes fixes the issues. Claws 3.10.1 Win 7 Ultimate SP1 - initial load is correct, but once claws tries to sync mail, it locks up and never releases (even after days). Claws is weird like that. Sylpheed 3.4.2 Win 7 Ultimate SP1 - mail list always looks fine, but sometimes clicking a message shows "can't display" in the preview pane - "get messages" restores access to messages. Thunderbird 31.5 Linux Mint 17 Qaina 3.13.0-24-generic - messages disappear and reappear with checks somewhat randomly. - Sometimes full redownload of folders is triggered, also seems random - Copies of messages appear, sometimes multiplying with each mail check - The summary information in the list pane doesn't match the message headers in the preview pane - wrong message total (every other client agrees on 2576 but TB-linux says 3242, perhaps counting dups) Claws 3.9.3 Linux Mint 17 Qaina 3.13.0-24-generic - Occasionally shows "this message can't be displayed" - executing a "get mail" fixes the error K-9 5.004 Android 4.3 - messages appear and then disappear on the next check - message body is occasionally blank (only subject and arrival time appear, no body preview line, clicking on the message shows "no text" *Server artifacts:* 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) or this error: Apr 15 10:04:00 indexer-worker(user at domain.com): Warning: Maildir /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new UID (old uid=306803, file=1428785463.M645546P27215.host,S=5389,W=5442:2,S) # grep -c "Expunged message reappeared" dovecot.log.0 8981 The first entry in dovecot.log.0 is at Apr 15 10:00:12, and the last entry at Apr 15 12:00:13; Dovecot is logging 4,490 expunged message reappeared messages per hour. Note the server has 4 accounts set up and very limited traffic, so 4,490 per hour would seem like a lot of anything to be logged. # doveadm dump -t mailboxlog /mail/domain.com/user #0: rename 000000803de108b60f00000000000000 (1969-12-31 16:00:00) #24: 00000000000000000000000000000000 (1969-12-31 16:00:00) #48: 000000000000000000000000c8272100 (1969-12-31 16:01:04) #72: 00002e61726368697665732e32303031 (2031-02-20 10:50:40) Fatal: rec read() 10 != 24 "Fatal" seems like an error. I do not see much argument with the assertion that 10 != 24. # doveadm dump -t fts-expunge-log /mail/domain.com/user Fatal: Invalid record_size=2147483648 at offset 0 dovecot-debug.log examples follow after # dovecot -n output, which follows "fixes tried:" *Fixes Tried* # doveadm purge -A # doveadm fts rescan -u user at domain.com # doveadm -Dv index -u user INBOX # doveadm force-resync -u user INBOX I've set mbox_dirty_syncs = no mbox_lazy_writes = no ...in an attempt to fix the problem, but none did. I tried removing most of my customizations one by one and testing, but the problem has not been improved. I strongly suspect that the index files are getting thrashed or otherwise abused. I have no idea what's triggering whatever event is resulting in the thousands of expunged messages reappearing, but the client artifacts suggest a mismatch between cache or index files and files on disk: UID, keywords, and set date appear as if from cache but the body of the message does not. It seems as if the UID doesn't match a message on disk any more, which soon gets automatically fixed and everything syncs again until something re-triggers - a false expunge perhaps? Or perhaps the transaction log is suffering some sort of ongoing abuse? *dovecot -n* # dovecot -n # 2.2.16: /usr/local/etc/dovecot/dovecot.conf # Pigeonhole version 0.4.7 # OS: FreeBSD 10.1-RELEASE amd64 auth_default_realm = blackrosetech.com auth_mechanisms = plain login auth_realms = blackrosetech.com eroticanarchy.org debug_log_path = /var/log/dovecot-debug.log deliver_log_format = msgid=%m: %f $p %$ disable_plaintext_auth = no first_valid_gid = 5000 first_valid_uid = 5000 hostname = blackrosetech.com info_log_path = /var/log/dovecot-info.log last_valid_gid = 5000 last_valid_uid = 5000 lda_mailbox_autocreate = yes listen = 10.3.69.135 log_path = /var/log/dovecot.log mail_debug = yes mail_gid = 5000 mail_location = maildir:~:CONTROL=/var/no-quota/%u mail_plugins = quota mail_log notify fts fts_lucene mail_temp_dir = /var/tmp mail_uid = 5000 managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate spamtest spamtestplus editheader mbox_dirty_syncs = no mbox_lazy_writes = no namespace inbox { inbox = yes location mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix } passdb { args = /usr/local/etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { expire = Trash fts = lucene fts_autoindex = yes fts_lucene = whitespace_chars=@. mime_parts mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size quota = maildir:User quota quota_exceeded_message = Storage quota for this account has been exceeded, please try again later. quota_rule = *:storage=50G quota_rule2 = Trash:storage=+30%% quota_rule3 = Sent:storage=+30%% quota_warning = storage=90%% quota-warning 90 %u quota_warning2 = storage=75%% quota-warning 75 %u sieve = ~/.dovecot.sieve sieve_before = /usr/local/etc/dovecot/sieve/ sieve_dir = ~/sieve sieve_extensions = +spamtest +spamtestplus +relational +comparator-i;ascii-numeric +editheader sieve_global_dir = /usr/local/etc/dovecot/sieve } postmaster_address = gessel at blackrosetech.com protocols = imap lmtp sieve sieve sendmail_path = /usr/local/sbin/sendmail service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } unix_listener auth-userdb { group = vmail mode = 0666 user = vmail } } service managesieve-login { inet_listener sieve { port = 4190 } service_count = 1 vsz_limit = 128 M } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = vmail } ssl = required ssl_cert = </usr/local/etc/ca/shiofuki-cert.pem ssl_key = </usr/local/etc/ca/shiofuki-unencrypted-key.pem ssl_prefer_server_ciphers = yes userdb { driver = prefetch } userdb { args = /usr/local/etc/dovecot/dovecot-sql.conf.ext driver = sql } protocol lda { mail_plugins = quota mail_log notify fts fts_lucene sieve } protocol imap { mail_max_userip_connections = 20 mail_plugins = quota mail_log notify fts fts_lucene imap_quota } protocol lmtp { mail_plugins = quota mail_log notify fts fts_lucene sieve } I appreciate any assistance or insight, -David *dovecot-debug.log excerpts* Apr 15 13:17:26 indexer-worker(user at domain.com): user-lookup(user at domain.com)Debug: auth input: user at domain.com home=/mail/domain.com/user/ mail=maildir:~/ uid=5000 gid=5000 quota_rule=*:bytes=0 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 argsApr 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/, altApr 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 argsApr 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=, altApr 15 13:49:32 lda(user at domain.com): Debug: Quota root: name=User quota backend=maildir argsApr 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=, altApr 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 argsApr 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 argsApr 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=
Edgar Pettijohn III
2015-Apr-16 02:10 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
> > mail_location = maildir:~:CONTROL=/var/no-quota/%uAt first glance the above looks like it may be wrong or a typo. I don't remember now why I added the following, but it seems like it may be worth a shot: imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags> > mbox_dirty_syncs = no > mbox_lazy_writes = noPretty sure the above is for mbox if you are using maildir I don't think they apply, but I could be wrong. Good luck. Edgar
David Gessel
2015-Apr-16 03:21 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
Edgar, Thank you very much for your help. -------- Original Message -------- Subject: Re: Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads From: Edgar Pettijohn III <edgar at pettijohn-web.com> To: David Gessel <gessel at blackrosetech.com> Date: Thu Apr 16 2015 05:10:50 GMT+0300 (Arabic Standard Time)>> >> mail_location = maildir:~:CONTROL=/var/no-quota/%u > > At first glance the above looks like it may be wrong or a typo. >It does what I expect: mail directories are virtual and look like /mail/domain.tld/user/cur /mail/domain.tld/user/.Sent/cur That's a little different than one would use for home directories where it would make sense to have something like /usr/home/user/maildir/INBOX/ control ends up looking like /var/no-quota/user at domain.tld/.INBOX I suppose "no-quota" was taken a little literally from the examples. I worried a bit that the lack of Maildir in the directory path might confuse something, but so far all clients can enumerate the IMAP structure.> I don't remember now why I added the following, but it seems like it may be worth a shot: > > imap_client_workarounds = delay-newmail tb-extra-mailbox-sep tb-lsub-flags >>I had tb-extra-mailbox-sep enabled, but on closer read it is only required if LAYOUT=fs, which I am not using so I removed it to simplify my options. I don't think it did anything better or worse being there. The documentation says delay-newmail is for outlook express 6 I haven't seen tb-lsub-flags - it seems to have been introduced in 2011 to help TB understand folders of folders. I'll give it a try, but I don't think it will impact the problems I'm seeing across so many clients.>> mbox_dirty_syncs = no >> mbox_lazy_writes = no > > Pretty sure the above is for mbox if you are using maildir I don't think they apply, but I could be wrong.I think you're right, and that would explain why they make no difference.> > Good luck. > > Edgar >
Steffen Kaiser
2015-Apr-16 06:56 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
-----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 = noyou are using Maildir, no? They don't effect Maildir.> mail_location = maildir:~:CONTROL=/var/no-quota/%uthis 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_luceneI 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-----
David Gessel
2015-Apr-16 14:13 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
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-----
Timo Sirainen
2015-Apr-16 18:31 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
On 16 Apr 2015, at 04:45, David Gessel <gessel at blackrosetech.com> 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.What were you running before Dovecot v2.2.16? An earlier Dovecot? A whole different system?> 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) > > or this error: > Apr 15 10:04:00 indexer-worker(user at domain.com): Warning: Maildir /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new UID (old uid=306803, file=1428785463.M645546P27215.host,S=5389,W=5442:2,S)..> The first entry in dovecot.log.0 is at Apr 15 10:00:12, and the last entry at Apr 15 12:00:13; Dovecot is logging 4,490 expunged message reappeared messages per hour. Note the server has 4 accounts set up and very limited traffic, so 4,490 per hour would seem like a lot of anything to be logged.These really shouldn't be happening..
David Gessel
2015-Apr-17 00:30 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
Hi Timo, Thank you for the reply. It is very much appreciated. -------- Original Message -------- Subject: Re: Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads From: Timo Sirainen <tss at iki.fi> To: David Gessel <gessel at blackrosetech.com> Date: Thu Apr 16 2015 21:31:30 GMT+0300 (Arabic Standard Time)> On 16 Apr 2015, at 04:45, David Gessel <gessel at blackrosetech.com> 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. > > What were you running before Dovecot v2.2.16? An earlier Dovecot? A whole different system?I migrated from Cyrus to Dovecot in July of last year on version 2.2.13. The issues started then and haven't really ever mitigated, though my impression (without any real data to back it up) is that it is more of a problem now, particularly mail appear/disappear issues. The first issue I noticed was unexpectedly frequent full resyncs in TB.> >> 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) >> >> or this error: >> Apr 15 10:04:00 indexer-worker(user at domain.com): Warning: Maildir /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new UID (old uid=306803, file=1428785463.M645546P27215.host,S=5389,W=5442:2,S) > .. >> The first entry in dovecot.log.0 is at Apr 15 10:00:12, and the last entry at Apr 15 12:00:13; Dovecot is logging 4,490 expunged message reappeared messages per hour. Note the server has 4 accounts set up and very limited traffic, so 4,490 per hour would seem like a lot of anything to be logged. > > These really shouldn't be happening.. >I didn't think so. I've contemplated migrating to sdbox, but Maildir shouldn't be a problem, I don't think. Things that strike me as possibly moving my config out of the well-tested regime include (not that anything is unique, but there may not be that many people testing all of the following): FreeBSD 10.1 ZFS mail_location = maildir:~/:CONTROL=/var/no-quota/%u FTS-Lucene Sieve/lmtp Quota Not that anything looks suspicious. The logs don't seem to indicate any reason for the "Expunged message reappeared, giving a new UID" errors. Is there someplace else the cause might be logged?
David Gessel
2015-Apr-17 00:47 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
scanning the logs for occurrences of "error," I find: # grep error dovecot* dovecot-info.log:Apr 15 17:01:09 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=, size=5887 dovecot-info.log:Apr 16 03:06:48 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<20150416100642.CA9C824764 at host2.localdomain>, size=13237 dovecot-info.log:Apr 16 17:01:18 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=, size=5887 dovecot-info.log.0:Apr 14 13:24:07 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<CAFOe2y4AwkM_BnkGNssLKkXRFJRk1GoAo7y6T7igTwtFMQk28Q at mail.gmail.tld>, size=3033 dovecot-info.log.0:Apr 14 13:24:07 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<cf8d60100fb6d439c559221f00df2f37f80.20150414175622 at mail100.atl31.mcdlv.net>, size=32589 dovecot-info.log.0:Apr 14 13:24:07 lda(user2 at domain2.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<23233383_24761373-24761373 at sbe203.redbeanforhealthopen.ninja>, size=6951 dovecot-info.log.0:Apr 14 13:24:07 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<93B38E8FD4B2741936862E3F@[10.0.248.3]>, size=2197 dovecot-info.log.0:Apr 14 13:24:07 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<4A13BE2E2FC7C49B7112BEE5@[10.0.248.3]>, size=4700 dovecot-info.log.0:Apr 14 13:29:07 lda(user2 at domain2.tld): Info: copy from stdin: box=INBOX, uid=952044, msgid=<2361227557511242361114254436978565 at ddxlohivv.errorsinvolved.tld>, size=6891 dovecot-info.log.0:Apr 14 13:34:07 lda(user1 at domain1.tld): Info: copy from stdin: box=Bulkmail, uid=error, msgid=<1120736677264.1115884694416.1417834012.0.291256JL.1002 at scheduler.constantcon..., size=44835 dovecot-info.log.0:Apr 14 13:34:07 lda(user1 at domain1.tld): Info: copy from stdin: box=Bulkmail, uid=error, msgid=<cm.050532.qulthjk.jyntyklj.r at cmail20.tld>, size=42787 dovecot-info.log.0:Apr 14 13:34:07 lda(user2 at domain2.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<63b529fb59de3613763afced1552234b_4334516_4774565 at sbe213.proslimfitbody.ninja>, size=4407 dovecot-info.log.0:Apr 14 13:39:07 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<cec4d3a3384c6e714e89d33d4a113800-m511477 at pfsense.org>, size=2941 dovecot-info.log.0:Apr 14 13:59:07 lda(user2 at domain2.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<22304076-63b529fb59de3613763afced1552234b.63b529fb59de3613763afced1552234b at s..., size=4492 dovecot-info.log.0:Apr 14 17:01:08 lda(user1 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=, size=5887 dovecot-info.log.0:Apr 15 17:00:09 lda(user3 at domain1.tld): Info: copy from stdin: box=INBOX, uid=error, msgid=<201504160000.t3G005Eu034535 at brunch.is>, size=1762 dovecot.log.9:Apr 15 11:02:42 imap(user1 at domain1.tld): Error: Log synchronization error at seq=3274,offset=152 for /mail/domain1.tld/user1//dovecot.index: Append with UID 302382, but next_uid = 2419524 Not a lot of errors, but not zero either. -------- Original Message -------- Subject: Re: Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads From: Timo Sirainen <tss at iki.fi> To: David Gessel <gessel at blackrosetech.com> Date: Thu Apr 16 2015 21:31:30 GMT+0300 (Arabic Standard Time)> On 16 Apr 2015, at 04:45, David Gessel <gessel at blackrosetech.com> 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. > > What were you running before Dovecot v2.2.16? An earlier Dovecot? A whole different system? > >> 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) >> >> or this error: >> Apr 15 10:04:00 indexer-worker(user at domain.com): Warning: Maildir /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new UID (old uid=306803, file=1428785463.M645546P27215.host,S=5389,W=5442:2,S) > .. >> The first entry in dovecot.log.0 is at Apr 15 10:00:12, and the last entry at Apr 15 12:00:13; Dovecot is logging 4,490 expunged message reappeared messages per hour. Note the server has 4 accounts set up and very limited traffic, so 4,490 per hour would seem like a lot of anything to be logged. > > These really shouldn't be happening.. >
David Gessel
2015-Apr-18 12:02 UTC
Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
-------- Original Message -------- Subject: Re: Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads From: Timo Sirainen <tss at iki.fi> To: David Gessel <gessel at blackrosetech.com> Date: Thu Apr 16 2015 21:31:30 GMT+0300 (Arabic Standard Time)> On 16 Apr 2015, at 04:45, David Gessel <gessel at blackrosetech.com> 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. > > What were you running before Dovecot v2.2.16? An earlier Dovecot? A whole different system? > >> 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) >> >> or this error: >> Apr 15 10:04:00 indexer-worker(user at domain.com): Warning: Maildir /mail/domain.com/user//.Sent: Expunged message reappeared, giving a new UID (old uid=306803, file=1428785463.M645546P27215.host,S=5389,W=5442:2,S) > .. >> The first entry in dovecot.log.0 is at Apr 15 10:00:12, and the last entry at Apr 15 12:00:13; Dovecot is logging 4,490 expunged message reappeared messages per hour. Note the server has 4 accounts set up and very limited traffic, so 4,490 per hour would seem like a lot of anything to be logged. > > These really shouldn't be happening.. >One possibility is that there is a scrub/verify routine running that is checking the actual size vs. reported size of messages, and perhaps that routine doesn't know about ZFS compression: zroot/ezjail used 117G - zroot/ezjail compressratio 1.25x - zroot/ezjail compression lz4 local zroot/ezjail logicalused 137G - and is seeing something anomalous and trying to "fix" that, triggering a rescan. A long shot and seems unlikely, but I have no other ideas. I also note from the documentation on the wiki: "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. " ...which are the right symptoms, but seems unlikely to be the right cause. And that: "Maildir format is somewhat compatible with MH format. This is sometimes a problem when people configure their procmail to deliver mails to Maildir/new. This makes procmail create the messages in MH format, which basically means that the file is called msg.inode_number. While this appears to work first, after expunging messages from the maildir the inodes are freed and will be reused later. This means that another file with the same name may come to the maildir, which makes Dovecot think that an expunged file reappeared into the mailbox and an error is logged. " ...which is exactly the error, but the And since I'm using Dovecot LMTP/LDA, it seems odd that errors would be generated. My main.cf config includes: virtual_transport = dovecot dovecot_destination_recipient_limit = 1 home_mailbox = Maildir/ mail_spool_directory = /mail mailbox_command = /usr/local/libexec/dovecot/deliver mailbox_transport = dovecot
Reasonably Related Threads
- Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
- Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
- Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
- Sieve permissions issue following update
- Dovecot/K9/Thunderbird IMAP interaction issues: replicated messages, constant reloading (TB) & missing new messages (K-9)