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@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@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@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@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 =
I appreciate any assistance or insight,
-David
*dovecot-debug.log excerpts*
Apr 15 13:17:26 indexer-worker(user@domain.com): user-lookup(user@domain.com)Debug: auth input: user@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@domain.com): user-lookup(user@domain.com)Debug: Added userdb setting: mail=maildir:~/ Apr 15 13:17:26 indexer-worker(user@domain.com): user-lookup(user@domain.com)Debug: Added userdb setting: plugin/quota_rule=*:bytes=0 Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Effective uid=5000, gid=5000, home=/mail/domain.com/user/ Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota root: name=User quota backend=maildir args= Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota rule: root=User quota mailbox=* bytes=0 messages=0 Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota rule: root=User quota mailbox=Trash bytes=0 (30%) messages=0 Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota rule: root=User quota mailbox=Sent bytes=0 (30%) messages=0 Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota warning: bytes=0 (90%) messages=0 reverse=no command=quota-warning 90 user@domain.com Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota warning: bytes=0 (75%) messages=0 reverse=no command=quota-warning 75 user@domain.com Apr 15 13:17:26 indexer-worker(user@domain.com): Debug: Quota grace: root=User quota bytes=0 (10%) Apr 15 13:17:26 indexer-worker(user@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@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@domain.com): Debug: Ignoring unknown cache field: pop3.order Apr 15 13:17:27 indexer-worker(user@domain.com): Debug: Ignoring unknown cache field: binary.parts Apr 15 13:17:27 indexer-worker(user@domain.com): Debug: Ignoring unknown cache field: body.snippet
Apr 15 13:44:25 lda(user@domain.com): Debug: Quota root: name=User quota
backend=maildir args=
Apr 15 13:44:25 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=* bytes=53687091200 messages=0
Apr 15 13:44:25 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=Trash bytes=+16106127360 (30%) messages=0
Apr 15 13:44:25 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=Sent bytes=+16106127360 (30%) messages=0
Apr 15 13:44:25 lda(user@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@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@domain.com): Debug: Quota grace: root=User quota
bytes=5368709120 (10%)
Apr 15 13:44:25 lda(user@domain.com): Debug: none: root=, index=,
indexpvt=, control=, inbox=, alt=
Apr 15 13:49:32 lda(user@domain.com): Debug: Quota root: name=User quota
backend=maildir args=
Apr 15 13:49:32 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=* bytes=53687091200 messages=0
Apr 15 13:49:32 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=Trash bytes=+16106127360 (30%) messages=0
Apr 15 13:49:32 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=Sent bytes=+16106127360 (30%) messages=0
Apr 15 13:49:32 lda(user@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@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@domain.com): Debug: Quota grace: root=User quota
bytes=5368709120 (10%)
Apr 15 13:49:32 lda(user@domain.com): Debug: none: root=, index=,
indexpvt=, control=, inbox=, alt=
Apr 15 13:49:41 lda(user@domain.com): Debug: sieve: file storage: Using
script storage path: /mail/domain.com/user//sieve
Apr 15 13:49:41 lda(user@domain.com): Debug: sieve: file storage: Relative
path to sieve storage in active link: sieve/
Apr 15 13:49:41 lda(user@domain.com): Debug: sieve: file script: Opened
script Forwards' from /mail/domain.com/user/sieve/Forwards.sieve'
Apr 15 13:49:41 lda(user@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@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@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@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@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@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@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@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@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@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@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@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@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@domain.com): Debug: sieve: Script binary
/mail/domain.com/user/.dovecot.svbin successfully loaded
Apr 15 13:49:41 lda(user@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@domain.com): Debug: sieve: Executing script from
`/mail/domain.com/user/.dovecot.svbin'
Apr 15 13:49:41 lda(user@domain.com): Debug: Quota root: name=User quota
backend=maildir args=
Apr 15 13:49:41 lda(user@domain.com): Debug: Quota rule: root=User quota
mailbox=* bytes=53687091200 messages=0
Apr 15 13:30:31 imap(user@domain.com): Debug: Loading modules from directory: /usr/local/lib/dovecot Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib11_imap_quota_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib15_notify_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib20_fts_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib20_mail_log_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Module loaded: /usr/local/lib/dovecot/lib21_fts_lucene_plugin.so Apr 15 13:30:31 imap(user@domain.com): Debug: Added userdb setting: plugin/quota_rule=*:bytes=0 Apr 15 13:30:31 imap(user@domain.com): Debug: Effective uid=5000, gid=5000, home=/mail/domain.com/user/ Apr 15 13:30:31 imap(user@domain.com): Debug: Quota root: name=User quota backend=maildir args= Apr 15 13:30:31 imap(user@domain.com): Debug: Quota rule: root=User quota mailbox=* bytes=0 messages=0 Apr 15 13:30:31 imap(user@domain.com): Debug: Quota rule: root=User quota mailbox=Trash bytes=0 (30%) messages=0 Apr 15 13:30:31 imap(user@domain.com): Debug: Quota rule: root=User quota mailbox=Sent bytes=0 (30%) messages=0 Apr 15 13:30:31 imap(user@domain.com): Debug: Quota warning: bytes=0 (90%) messages=0 reverse=no command=quota-warning 90 user@domain.com Apr 15 13:30:31 imap(user@domain.com): Debug: Quota warning: bytes=0 (75%) messages=0 reverse=no command=quota-warning 75 user@domain.com Apr 15 13:30:31 imap(user@domain.com): Debug: Quota grace: root=User quota bytes=0 (10%) Apr 15 13:30:31 imap(user@domain.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~:CONTROL=/var/no-quota/user@domain.com Apr 15 13:30:31 imap(user@domain.com): Debug: maildir++: root=/mail/domain.com/user/, index=, indexpvt=, control=/var/no-quota/user@domain.com, inbox=/mail/domain.com/user/, alt=