dovecot - Jun 2015 - 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: Benny Pedersen <me at junc.eu>
To: dovecot at dovecot.org
Date: Mon Jun 01 2015 16:47:48 GMT+0300 (Arabic Standard Time)
> Alessio Cecchi skrev den 2015-06-01 15:29:
>> Il 20/05/2015 10:44, David Gessel ha scritto:
>>> Is there a way to completely disable caching on dovecot?
>>
>> Yes: mail_location = maildir:~/Maildir:INDEX=MEMORY
> 
> dont know if that really solve it, imho it just move the problem from disk
cache to memory cache, it does not imho disable it

It seemed to do the trick.  Behavior finally seems normal.  The best evidence: 
At 10:00:00-ish I made the change in the config file and at 10:02:29 I restarted
the server.

It is now after 17:14 in Oakland and the logs are quiet.

 09:00:06 host newsyslog[55292]: logfile turned over due to size>1000K
 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged message
reappeared, giving a new UID (old uid=3558585,
file=1434383291.M430136P55004.host,S=2380,W=2423:2,)
 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged message
reappeared, giving a new UID (old uid=3558586,
file=1434383253.M121801P54997.host,S=27419,W=28395:2,)
 09:01:28 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3558587,
file=1434383997.M731644P55286.host,S=7334,W=7513:2,)
 09:07:49 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3561318,
file=1434383997.M731644P55286.host,S=7334,W=7513:2,)
 09:08:49 imap(user2): Warning: Maildir /mail/dom2/dmag/: Expunged message
reappeared, giving a new UID (old uid=1846654,
file=1434381278.M451318P54372.host,S=5013,W=5116:2,)
 09:09:48 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged message
reappeared, giving a new UID (old uid=3561319,
file=1405470941.M117568P19536.host.dom1.com,S=8266,W=8382:2,)
 09:21:02 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged message
reappeared, giving a new UID (old uid=3564050,
file=1434384469.M876726P55434.host,S=7297,W=7418:2,)
 09:24:49 imap(user2): Warning: Maildir /mail/dom2/dmag/: Expunged message
reappeared, giving a new UID (old uid=1847030,
file=1434383414.M615990P55039.host,S=9890,W=10269:2,)
 09:24:49 imap(user2): Warning: Maildir /mail/dom2/dmag/: Expunged message
reappeared, giving a new UID (old uid=1847031,
file=1434384445.M934994P55428.host,S=3405,W=3487:2,)
 09:24:49 imap(user2): Warning: Maildir /mail/dom2/dmag/: Expunged message
reappeared, giving a new UID (old uid=1847032,
file=1434381278.M451318P54372.host,S=5013,W=5116:2,)
 09:27:18 indexer-worker(user2): Warning: Maildir /mail/dom2/dmag/: Expunged
message reappeared, giving a new UID (old uid=1847033,
file=1434384562.M535709P55456.host,S=3403,W=3485:2,)
 09:42:41 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3565416,
file=1434385257.M437928P55657.host,S=176241,W=178722:2,)
 09:47:18 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3568150,
file=1434386561.M197796P56113.host,S=905854,W=917647:2,)
 09:47:18 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3568151,
file=1434385257.M437928P55657.host,S=176241,W=178722:2,)
 09:47:23 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged message
reappeared, giving a new UID (old uid=3568152,
file=1434386561.M197796P56113.host,S=905854,W=917647:2,)
 09:53:34 imap(user2): Warning: Maildir /mail/dom2/dmag/: Expunged message
reappeared, giving a new UID (old uid=1847228,
file=1434384562.M535709P55456.host,S=3403,W=3485:2,)
 09:59:22 master: Warning: Killed with signal 15 (by pid=56486 uid=0 code=kill)
 10:00:57 lda(user3): Warning: Maildir /mail/dom1.com/user3/: UIDVALIDITY
changed (1404858902 -> 1433446125)
 10:00:57 indexer-worker(user3): Warning: fts-lucene: Settings have changed,
rebuilding index for mailbox
 10:00:57 indexer-worker(user1): Warning: Maildir /mail/dom1.com/user1/:
Expunged message reappeared, giving a new UID (old uid=3569520,
file=1434386838.M74634P56231.host,S=905827,W=917620:2,)
 10:02:29 master: Warning: Killed with signal 15 (by pid=66696 uid=0 code=kill)
 10:05:13 indexer-worker(user1): Warning: fts-lucene: Settings have changed,
rebuilding index for mailbox
 10:05:13 indexer-worker(user1): Error:
stat(/mail/dom1.com/user1//.dovecot.sieve/tmp) failed: Not a directory
 10:08:09 indexer-worker(user3): Warning: fts-lucene: Settings have changed,
rebuilding index for mailbox
 10:17:00 indexer-worker(user2): Warning: fts-lucene: Settings have changed,
rebuilding index for mailbox
 15:24:16 imap(user1): Error: stat(/mail/dom1.com/user1//.dovecot.sieve/tmp)
failed: Not a directory

The last log file was turned over when it got greater than 1000K.  It covered
1312 minutes and 3726 "expunged Message" warnings or one every 21
seconds.  There hasn't been a single one in the 7+ hours since I moved the
index to MEMORY.

Whatever is confusing the index state on disk, it is not happening in RAM.

On 16 Jun 2015, at 03:50, David Gessel <gessel at blackrosetech.com>
wrote:
> 
>> Alessio Cecchi skrev den 2015-06-01 15:29:
>>> Il 20/05/2015 10:44, David Gessel ha scritto:
>>>> Is there a way to completely disable caching on dovecot?
>>> 
>>> Yes: mail_location = maildir:~/Maildir:INDEX=MEMORY
>> 
>> dont know if that really solve it, imho it just move the problem from
disk cache to memory cache, it does not imho disable it
> 
> 
> It seemed to do the trick.  Behavior finally seems normal.  The best
evidence:  At 10:00:00-ish I made the change in the config file and at 10:02:29
I restarted the server.
> 
> It is now after 17:14 in Oakland and the logs are quiet.
> 
> 09:00:06 host newsyslog[55292]: logfile turned over due to size>1000K
> 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged
message reappeared, giving a new UID (old uid=3558585,
file=1434383291.M430136P55004.host,S=2380,W=2423:2,)
> 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged
message reappeared, giving a new UID (old uid=3558586,
file=1434383253.M121801P54997.host,S=27419,W=28395:2,)
..
> The last log file was turned over when it got greater than 1000K.  It
covered 1312 minutes and 3726 "expunged Message" warnings or one every
21 seconds.  There hasn't been a single one in the 7+ hours since I moved
the index to MEMORY.
> 
> Whatever is confusing the index state on disk, it is not happening in RAM. 
Well, it's also possible that the confusion is still happening, but Dovecot
just doesn't notice it. If it is, IMAP clients may randomly not see all
messages or may otherwise have strange behavior.

-------- 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: Wed Jun 17 2015 14:29:08 GMT+0300 (Arabic Standard Time)
> On 16 Jun 2015, at 03:50, David Gessel <gessel at blackrosetech.com>
wrote:
>>
>>> Alessio Cecchi skrev den 2015-06-01 15:29:
>>>> Il 20/05/2015 10:44, David Gessel ha scritto:
>>>>> Is there a way to completely disable caching on dovecot?
>>>>
>>>> Yes: mail_location = maildir:~/Maildir:INDEX=MEMORY
>>>
>>> dont know if that really solve it, imho it just move the problem
from disk cache to memory cache, it does not imho disable it
>>
>>
>> It seemed to do the trick.  Behavior finally seems normal.  The best
evidence:  At 10:00:00-ish I made the change in the config file and at 10:02:29
I restarted the server.
>>
>> It is now after 17:14 in Oakland and the logs are quiet.
>>
>> 09:00:06 host newsyslog[55292]: logfile turned over due to
size>1000K
>> 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged
message reappeared, giving a new UID (old uid=3558585,
file=1434383291.M430136P55004.host,S=2380,W=2423:2,)
>> 09:00:08 imap(user1): Warning: Maildir /mail/dom1.com/user1/: Expunged
message reappeared, giving a new UID (old uid=3558586,
file=1434383253.M121801P54997.host,S=27419,W=28395:2,)
> ..
>> The last log file was turned over when it got greater than 1000K.  It
covered 1312 minutes and 3726 "expunged Message" warnings or one every
21 seconds.  There hasn't been a single one in the 7+ hours since I moved
the index to MEMORY.
>>
>> Whatever is confusing the index state on disk, it is not happening in
RAM.
> 
> Well, it's also possible that the confusion is still happening, but
Dovecot just doesn't notice it. If it is, IMAP clients may randomly not see
all messages or may otherwise have strange behavior.
> 
As far as anyone has been able to determine, all artifacts are resolved.  I
believe it is fair to say "SOLVED."  As I often start trying to solve
problems by searching the list archives, I'll append my description of the
artifacts as googlebait to the bottom of this message.

I am curious if setting INDEX=MEMORY "disables the index completely"
as per http://wiki2.dovecot.org/MailLocation:

"If you really want to, you can also disable the index files completely by
appending :INDEX=MEMORY."

Or if there are index files in memory as one might assume taking the directive
literally, and if so, if these are functionally equivalent to, say, Courier
IMAP's caching model.

Performance seems excellent, all features seem to work fine.  A list of the
artifacts that were observed before setting INDEX=MEMORY, all of which have been
resolved by the directive change include:

*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

*All resolved with the fix*

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.

*All resolved with the fix*


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.
- Initial load is very fast

* Mostly works *
- claws still refuses to respond to the "exit" command and has to be
force-quit.  This is a widely reported claws issue.
- All mail tasks work fine, no artifacts other than refusing to quit.


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

*Resolved with the fix*


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)

*All resolved with the fix*

Claws 3.9.3 Linux Mint 17 Qaina 3.13.0-24-generic

- Occasionally shows "this message can't be displayed"

(haven't tested, but I'm guessing it is fixed)

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"
- K-9 reports an absurdly large number of messages to download
- K-9's notification message appears constantly with notifications of
already downloaded messages
- Battery usage is excessive (K-9 sometimes uses more battery than the display)
- excessive bandwidth usage

*All resolved with the fix*

*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

On my server, "Expunged message reappeared" errors were being logged
at a rate of about 3-5,000 per hour.  After the fix, the error has not been
logged at all.


# 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

After the fix:

# doveadm dump -t mailboxlog /mail/domain.com/user
#0: rename 00000080fba020fd0600000000000000 (1969-12-31 16:00:00)
#24:  00000000000000000000000000000000 (1969-12-31 16:00:00)
#48:  000000000000000000000000e9a83900 (1969-12-31 16:02:08)
#72:  0000646f7665636f742d75696476616c (2026-01-11 19:24:36)
Fatal: rec read() 10 != 24

- OK, that's not fixed. :-(


# doveadm dump -t fts-expunge-log /mail/domain.com/user
Fatal: Invalid record_size=2147483648 at offset 0 

After the fix:
# doveadm dump -t fts-expunge-log /mail/domain.com/user
Fatal: Invalid record_size=2147483648 at offset 0


Perhaps there are still some corrupt messages?  Any way to clean those up?  This
is either a different issue completely or it is a persistent artifact of the
previous issue.  I have done a

# find /mail/ -name "dovecot*" -type f -delete

since changing the directive followed by a jail reboot, are there any other
files that should be deleted and allowed to recreate?  doveadm_ files? 
lucene-indexes?

 # doveadm dump -t log /mail/domain.com/user
version = 0.0
hdr size = 0
index id = 0
file seq = 0
prev file = 0/0
create stamp = 0
initial modseq = 0
compat flags = 0
record: offset=0, type=unknown: 80000000, size=broken (3)

perhaps the size values should be recomputed with
http://dovecot.org/tools/maildir-size-fix.pl ?

# doveadm dump -t thread /mail/domain.com/user
Fatal: mmap() failed: Invalid argument