thr3ads.net - dovecot - Dovecot 2.2.16: disappearing messages, mismatched summaries, duplicated messages, excessive full re-downloads [Apr 2015]

If this information is useful, please help other people find it:
Share via:

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

head link

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

> 
> mail_location = maildir:~:CONTROL=/var/no-quota/%u
At 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 = no
Pretty 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

head link

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

head link

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 = no
you are using Maildir, no? They don't effect Maildir.
> mail_location = maildir:~:CONTROL=/var/no-quota/%u
this one hits me:

http://wiki2.dovecot.org/VirtualUsers/Home
"Home directory shouldn't be the same as mail directory. It's
possible to
do that, but you might run into trouble with it sooner or later. Some 
problems with this are: " ...
> mail_plugins = quota mail_log notify fts fts_lucene
I don't run FTS, where does lucene store its files? In the user's home?
> Apr 15 13:17:26 indexer-worker(user at domain.com): 
> user-lookup(user at domain.com)Debug: Added userdb setting: mail=maildir:~/
> Apr 15 13:17:26 indexer-worker(user at domain.com): 
> user-lookup(user at domain.com)Debug: Added userdb setting: 
> plugin/quota_rule=*:bytes=0
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Effective
uid=5000,
> gid=5000, home=/mail/domain.com/user/
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota root:
name=User
> quota backend=maildir args> Apr 15 13:17:26 indexer-worker(user at
domain.com): Debug: Quota rule: root=User
> quota mailbox=* bytes=0 messages=0
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota rule:
root=User
> quota mailbox=Trash bytes=0 (30%) messages=0
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota rule:
root=User
> quota mailbox=Sent bytes=0 (30%) messages=0
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota warning: 
> bytes=0 (90%) messages=0 reverse=no command=quota-warning 90 user at
domain.com
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota warning: 
> bytes=0 (75%) messages=0 reverse=no command=quota-warning 75 user at
domain.com
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Quota grace: 
> root=User quota bytes=0 (10%)
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: Namespace inbox:
> type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, 
> subscriptions=yes location=maildir:~/
> Apr 15 13:17:26 indexer-worker(user at domain.com): Debug: maildir++: 
> root=/mail/domain.com/user/, index=, indexpvt=, control=, 
> inbox=/mail/domain.com/user/, alt> Apr 15 13:17:27 indexer-worker(user
at domain.com): Debug: Ignoring unknown
> cache field: pop3.order
> Apr 15 13:17:27 indexer-worker(user at domain.com): Debug: Ignoring unknown
> cache field: binary.parts
> Apr 15 13:17:27 indexer-worker(user at domain.com): Debug: Ignoring unknown
> cache field: body.snippet
>
>
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota root: name=User quota
> backend=maildir args> Apr 15 13:44:25 lda(user at domain.com): Debug:
Quota rule: root=User quota
> mailbox=* bytes=53687091200 messages=0
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota rule: root=User quota
> mailbox=Trash bytes=+16106127360 (30%) messages=0
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota rule: root=User quota
> mailbox=Sent bytes=+16106127360 (30%) messages=0
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota warning:
bytes=48318382080
> (90%) messages=0 reverse=no command=quota-warning 90 raw mail user
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota warning:
bytes=40265318400
> (75%) messages=0 reverse=no command=quota-warning 75 raw mail user
> Apr 15 13:44:25 lda(user at domain.com): Debug: Quota grace: root=User
quota
> bytes=5368709120 (10%)
> Apr 15 13:44:25 lda(user at domain.com): Debug: none: root=, index=,
indexpvt=,
> control=, inbox=, alt> Apr 15 13:49:32 lda(user at domain.com): Debug:
Quota root: name=User quota
> backend=maildir args> Apr 15 13:49:32 lda(user at domain.com): Debug:
Quota rule: root=User quota
> mailbox=* bytes=53687091200 messages=0
> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota rule: root=User quota
> mailbox=Trash bytes=+16106127360 (30%) messages=0
> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota rule: root=User quota
> mailbox=Sent bytes=+16106127360 (30%) messages=0
> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota warning:
bytes=48318382080
> (90%) messages=0 reverse=no command=quota-warning 90 raw mail user
> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota warning:
bytes=40265318400
> (75%) messages=0 reverse=no command=quota-warning 75 raw mail user
> Apr 15 13:49:32 lda(user at domain.com): Debug: Quota grace: root=User
quota
> bytes=5368709120 (10%)
> Apr 15 13:49:32 lda(user at domain.com): Debug: none: root=, index=,
indexpvt=,
> control=, inbox=, alt> Apr 15 13:49:41 lda(user at domain.com): Debug:
sieve: file storage: Using
> script storage path: /mail/domain.com/user//sieve
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file storage:
Relative
> path to sieve storage in active link: sieve/
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `Forwards' from `/mail/domain.com/user/sieve/Forwards.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Server_Msg' from 
> `/mail/domain.com/user/sieve/File_Server_Msg.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_SRL' from `/mail/domain.com/user/sieve/File_SRL.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_BULK' from
`/mail/domain.com/user/sieve/File_BULK.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Commerce' from
`/mail/domain.com/user/sieve/File_Commerce.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Impersonal' from 
> `/mail/domain.com/user/sieve/File_Impersonal.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Travel' from
`/mail/domain.com/user/sieve/File_Travel.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Tribe' from
`/mail/domain.com/user/sieve/File_Tribe.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Info' from
`/mail/domain.com/user/sieve/File_Info.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Lists' from
`/mail/domain.com/user/sieve/File_Lists.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Trash' from
`/mail/domain.com/user/sieve/File_Trash.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Security' from
`/mail/domain.com/user/sieve/File_Security.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Notifications' from 
> `/mail/domain.com/user/sieve/File_Notifications.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: file script: Opened 
> script `File_Spam' from
`/mail/domain.com/user/sieve/File_Spam.sieve'
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: Script binary 
> /mail/domain.com/user/.dovecot.svbin successfully loaded
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: binary save: not
saving
> binary /mail/domain.com/user/.dovecot.svbin, because it is already stored
> Apr 15 13:49:41 lda(user at domain.com): Debug: sieve: Executing script
from
> `/mail/domain.com/user/.dovecot.svbin'
> Apr 15 13:49:41 lda(user at domain.com): Debug: Quota root: name=User quota
> backend=maildir args> Apr 15 13:49:41 lda(user at domain.com): Debug:
Quota rule: root=User quota
> mailbox=* bytes=53687091200 messages=0
>
>
>
> Apr 15 13:30:31 imap(user at domain.com): Debug: Loading modules from
directory:
> /usr/local/lib/dovecot
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib10_quota_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib11_imap_quota_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib15_notify_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib20_fts_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib20_mail_log_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Module loaded: 
> /usr/local/lib/dovecot/lib21_fts_lucene_plugin.so
> Apr 15 13:30:31 imap(user at domain.com): Debug: Added userdb setting: 
> plugin/quota_rule=*:bytes=0
> Apr 15 13:30:31 imap(user at domain.com): Debug: Effective uid=5000,
gid=5000,
> home=/mail/domain.com/user/
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota root: name=User
quota
> backend=maildir args> Apr 15 13:30:31 imap(user at domain.com): Debug:
Quota rule: root=User quota
> mailbox=* bytes=0 messages=0
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota rule: root=User
quota
> mailbox=Trash bytes=0 (30%) messages=0
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota rule: root=User
quota
> mailbox=Sent bytes=0 (30%) messages=0
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota warning: bytes=0
(90%)
> messages=0 reverse=no command=quota-warning 90 user at domain.com
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota warning: bytes=0
(75%)
> messages=0 reverse=no command=quota-warning 75 user at domain.com
> Apr 15 13:30:31 imap(user at domain.com): Debug: Quota grace: root=User
quota
> bytes=0 (10%)
> Apr 15 13:30:31 imap(user at domain.com): Debug: Namespace inbox:
type=private,
> prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes 
> location=maildir:~:CONTROL=/var/no-quota/user at domain.com
> Apr 15 13:30:31 imap(user at domain.com): Debug: maildir++: 
> root=/mail/domain.com/user/, index=, indexpvt=, 
> control=/var/no-quota/user at domain.com, inbox=/mail/domain.com/user/,
alt>
- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1

iQEVAwUBVS9dNnz1H7kL/d9rAQLn8Af/cQ8BSg6cmUFj6qGVcQUglJkI8hjY3CQM
2MBI/qQbouo4hg3eQNOLX+MOYAGcCV2I+wM8WkOJkqOjPn8vBZACHe5Y860mBbEA
XipvGMML1DJt+4leNo/1jPpiFJEFZ3w9kFiCC+rPcjrTU8XV5g+l9RQDofu8vElZ
jySGQvH3Ml7kP2afTrqiBb3cwoQVLXMYUTsjw4csw0qn3lWB7i3yN/WACsBMFBP6
H0KnM99UUYbOJ4TMsBJ7aDXIUIvlu6Eo1oGznIsKiX1k6BoCPQtXwlxk4NJ6f8B/
SaGYf6FPSQmKaePTVwxJfSc8sTBxb+rG7DsZQnGjwZFtGH3ti810eg==6hFs
-----END PGP SIGNATURE-----

David Gessel

2015-Apr-16 14:13 UTC

head link

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

head link

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

head link

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

head link

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

head link

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

Seemingly Similar Threads

Search for more possibly parallel threads

dovecot - Apr 2015 - 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

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

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

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

Seemingly Similar Threads