dovecot - May 2014 - Index cache errors worse with 2.2.x

Hi!

I am getting "Cached message size smaller than expected" errors since
dovecot-2.1.x.
Until now, I thought that those errors don't do any harm, I assumed that the
cache will just be rebuilt after the error had been detected.

However, since dovecot 2.2.x (I tried 2.2.7 and 2.2.10), the errors sometimes
seem to actually cause mail access to fail.

With dovecot-2.1.1, only the first two messages were logged, since using 2.2.7
and 2.2.10, the "read ... failed: Invalid argument" sometimes appear:
-------------------- 8< --------------------
May  7 17:03:52 samba dovecot: imap(xyz): Error: Cached message size smaller
than expected (2246 < 2247)
May  7 17:03:52 samba dovecot: imap(xyz): Error: Corrupted index cache file
/home/xyz/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail
UID 11277
May  7 17:03:52 samba dovecot: imap(xyz): Error: read(/var/mail/xyz) failed:
Invalid argument
May  7 17:03:52 samba dovecot: imap(xyz): Error: read(/var/mail/xyz) failed:
Invalid argument (uid=11277)
-------------------- 8< --------------------

I am using dovecot on RHEL6 with mbox mailboxes. Message size differences are
always 1 byte.

Any hints would be appreciated!

Cheers,
--leo

P.S.: Those errors occur some times a day and affect different users..
(Upgrade 2.1.1 -> 2.2.7 was on 2013-11-22, 2.2.10 was installed on
2014-01-20.)

# for f in maillog* ; do echo -n "$f: "; grep "dovecot:.*Error:
read.*failed.*Invalid arg" $f | wc -l; done
maillog: 31
maillog-20130801: 0
maillog-20130901: 1
maillog-20131001: 0
maillog-20131101: 0
maillog-20131201: 30
maillog-20140101: 92
maillog-20140201: 110
maillog-20140301: 99
maillog-20140401: 133
maillog-20140501: 100

# for f in maillog* ; do echo -n "$f: "; grep "dovecot:.*Error:
Cached message size smaller than expected" $f | wc -l; done
maillog: 99
maillog-20130801: 465
maillog-20130901: 484
maillog-20131001: 512
maillog-20131101: 460
maillog-20131201: 520
maillog-20140101: 402
maillog-20140201: 400
maillog-20140301: 355
maillog-20140401: 481
maillog-20140501: 434

-- 
e-mail   ::: Leo.Bergolth (at) wu.ac.at
fax      ::: +43-1-31336-906050
location ::: IT-Services | Vienna University of Economics | Austria

On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth <leo at
strike.wu.ac.at> wrote:
> I am getting "Cached message size smaller than expected" errors
since dovecot-2.1.x.
Please provide enough info for someone to actually be able to attempt to 
help you.

At a bare minimum, you should *always* (not just for dovecot) provide at 
least the OS/ver and dovecot config (doveconf -n output).

Also, the further from 'default' settings your setup is, the more 
important it is to provide a description of your environment (ie, is 
this a single server or a member of a cluster? are you using NFS? etc)...

-- 

Best regards,

Charles

On 05/07/2014 10:38 PM, Alexander 'Leo' Bergolth
wrote:
> I am getting "Cached message size smaller than expected" errors
since dovecot-2.1.x.
> Until now, I thought that those errors don't do any harm, I assumed
that the cache will just be rebuilt after the error had been detected.
> 
> However, since dovecot 2.2.x (I tried 2.2.7 and 2.2.10), the errors
sometimes seem to actually cause mail access to fail.
dovecot 2.2.12 and 2.2.13 also show the same errors:
-------------------- 8< --------------------
May 13 10:38:07 samba dovecot: imap-login: Login: user=<xxx>,
method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=12503, secured,
session=<LMyp+0P5bgCsFzwB>
May 13 10:38:08 samba dovecot: imap(xxx): Error: Cached message size smaller
than expected (68196 < 68197)
May 13 10:38:08 samba dovecot: imap(xxx): Error: Corrupted index cache file
/home/xxx/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail
UID 1835
May 13 10:38:08 samba dovecot: imap(xxx): Error: read(/var/mail/xxx) failed:
Invalid argument (uid=1835)
May 13 10:38:08 samba dovecot: imap(xxx): Disconnected: Internal error occurred.
Refer to server log for more information. [2014-05-13 10:38:07] in=794
out=264037
-------------------- 8< --------------------

As before, message size difference is always 1 byte.

Is there any debug mode that could be used to collect more information without
flooding the server?

Cheers,
--leo
-- 
e-mail   ::: Leo.Bergolth (at) wu.ac.at   
fax      ::: +43-1-31336-906050
location ::: IT-Services | Vienna University of Economics | Austria