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

Sat Jun 20 15:20:37 UTC 2015

-------- 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