Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads
David Gessel
gessel at blackrosetech.com
Thu Apr 16 01:45:24 UTC 2015
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 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=
More information about the dovecot
mailing list