[Dovecot] Index cache errors worse with 2.2.x

Alexander 'Leo' Bergolth leo at strike.wu.ac.at
Fri May 23 09:54:32 UTC 2014


On 05/08/2014 11:59 AM, Alexander 'Leo' Bergolth wrote:
> On 05/08/2014 11:44 AM, Charles Marcus wrote:
>> 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.
>>
> I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same
> errors. ("Cached message size smaller than expected", sometimes followed
> by "read... Invalid argument".)

This really drives me to despair! :-(
Timo please help!

I also tried dovecot-2.2.13 and even downgraded to dovecot-2.1.17 now.
(Did a doveadm -v force-resync -u $user "*" for all users after changing versions.)
I can also see somehow similar problems on another box that uses (the rather old) dovecot 2.1.1.

I tried to add dotlock to mbox_write_locks since according to the source,
the LDA (maildrop) seems to try dotlock before fcntl.
I also changed fcntl to dotlock for locking index files. (lock_method = dotlock)
The only processes that access a users mailboxes are dovecot (imap and pop) and maildrop (LDA).

The only non-standard setup I can identify is that I am using an imap-postlogin script that dynamically adds some additional namespaces via environment variables for some users that have access to shared mailboxes.
But I doubt wether this can have an influence on the index.cache errors.

I'd greatly appreciate your help!

Thanks,
--leo

maillogs,dovecot config and additional information can be found at:
http://leo.kloburg.at/tmp/dovecot-index/



2.2.13 Errors:
-------------------- 8< --------------------
May 19 05:51:15 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (75357 < 75358)
May 19 05:51:15 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70929
May 19 05:51:15 samba dovecot: imap(USER1): Error: copy: i_stream_read() failed: Invalid argument
May 19 05:51:15 samba dovecot: imap(USER1): Error: mail parser: read(/var/mail/USER1, box=Trash) failed: Invalid argument
May 19 07:23:59 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (75357 < 75358)
May 19 07:23:59 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18322
May 19 07:23:59 samba dovecot: imap(USER2): Error: read(/var/mail/USER2) failed: Cached message size smaller than expected (75357 < 75358) (FETCH BODY[] for mailbox INBOX UID 18322)
May 19 07:48:11 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (13510 < 13511)
May 19 07:48:11 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 952
May 19 07:48:11 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Cached message size smaller than expected (13510 < 13511) (FETCH BODY[2] for mailbox INBOX UID 952)
May 19 07:58:45 samba dovecot: imap(USER4): Error: Cached message size smaller than expected (1892192 < 1892193)
May 19 07:58:45 samba dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 20561
May 19 07:58:45 samba dovecot: imap(USER4): Error: copy: i_stream_read() failed: Invalid argument
May 19 07:58:45 samba dovecot: imap(USER4): Error: mail parser: read(/var/mail/USER4, box=Stab) failed: Invalid argument
May 19 08:58:44 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (185239 < 185240)
May 19 08:58:44 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70934
May 19 08:58:44 samba dovecot: imap(USER1): Error: read(/var/mail/USER1) failed: Cached message size smaller than expected (185239 < 185240) (FETCH BODY[] for mailbox INBOX UID 70934)
May 19 09:00:00 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (185239 < 185240)
May 19 09:00:00 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18324
May 19 09:00:00 samba dovecot: imap(USER2): Error: copy: i_stream_read() failed: Invalid argument
May 19 09:00:00 samba dovecot: imap(USER2): Error: mail parser: read(/var/mail/USER2, box=Trash) failed: Invalid argument
May 19 09:56:47 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (1829385 < 1829386)
May 19 09:56:47 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70938
May 19 09:56:47 samba dovecot: imap(USER1): Error: copy: i_stream_read() failed: Invalid argument
May 19 09:56:47 samba dovecot: imap(USER1): Error: mail parser: read(/var/mail/USER1, box=Trash) failed: Invalid argument
May 19 10:11:48 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (75357 < 75358)
May 19 10:11:48 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 24136
May 19 10:11:48 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Cached message size smaller than expected (75357 < 75358) (FETCH BODY[] for mailbox INBOX UID 24136)
-------------------- 8< --------------------


2.1.17 Errors:
-------------------- 8< --------------------
May 22 12:36:29 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (63266 < 63267)
May 22 12:36:29 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 71075
May 22 12:38:01 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (221845 < 221846)
May 22 12:38:01 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 2871
May 22 12:38:01 samba dovecot: imap(USER2): Error: read(/var/mail/USER2) failed: Input/output error (FETCH for mailbox INBOX UID 2871)
May 22 12:38:02 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (221845 < 221846)
May 22 12:38:02 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 2871
May 22 12:56:02 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (57091 < 57092)
May 22 12:56:02 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18358
May 22 12:56:02 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Input/output error (FETCH for mailbox INBOX UID 18358)
May 22 12:56:11 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (57091 < 57092)
May 22 12:56:11 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18358
May 22 12:56:11 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Input/output error (FETCH for mailbox INBOX UID 18358)
May 22 13:21:26 samba dovecot: imap(USER4): Error: Cached message size smaller than expected (57091 < 57092)
May 22 13:21:26 samba dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11275
May 22 13:21:26 samba dovecot: imap(USER4): Error: read(/var/mail/USER4) failed: Input/output error (FETCH for mailbox INBOX UID 11275)
May 22 14:03:02 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (16034 < 16035)
May 22 14:03:02 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11394
May 22 14:03:02 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Input/output error (uid=11394)
May 22 14:35:49 samba dovecot: imap(USER6): Error: Cached message size smaller than expected (10925 < 10926)
May 22 14:35:49 samba dovecot: imap(USER6): Error: Corrupted index cache file /home/USER6/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 23149
May 22 14:43:08 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (616708 < 616709)
May 22 14:43:08 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 71078
May 22 14:43:08 samba dovecot: imap(USER1): Error: read(/var/mail/USER1) failed: Input/output error (FETCH for mailbox INBOX UID 71078)
May 22 14:51:52 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (10924 < 10925)
May 22 14:51:52 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11499
May 22 14:51:52 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Input/output error (uid=11499)
-------------------- 8< --------------------

2.1.1 on another box:
-------------------- 8< --------------------
Mar  4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2656 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size
Mar  4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2744 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size
Mar  4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2832 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size
Mar 10 07:27:00 strike dovecot: imap(USER2): Error: Cached message size larger than expected (10369 > 10337)
Mar 10 07:27:00 strike dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/Sent/dovecot.index.cache: Broken physical size for mail UID 606
Mar 10 07:27:00 strike dovecot: imap(USER2): Error: read(/home/USER2/mail/Sent) failed: Input/output error (FETCH for mailbox Sent UID 606)
Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Cached message size larger than expected (1066719 > 1065140)
Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 458
Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Cached message size larger than expected (1066719 > 1065140)
Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 458
Mar 11 10:45:21 strike dovecot: imap(USER3): Error: copy: i_stream_read() failed: Input/output error
Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Cached message size larger than expected (4093 > 3364)
Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 20089
Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Cached message size larger than expected (4093 > 3364)
Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 20089
Mar 17 19:47:29 strike dovecot: imap(USER4): Error: copy: i_stream_read() failed: Input/output error
Apr  2 18:06:39 strike dovecot: imap(USER5): Error: Log synchronization error at seq=1,offset=30176 for /home/USER5/mail/.imap/virus/dovecot.index: Extension header update points outside header size
Apr 16 18:49:26 strike dovecot: imap(USER4): Error: FETCH [] for mailbox Drafts UID 20428 got too little data: 9936 vs 10490
Apr 16 18:49:26 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken virtual size for mail UID 20428
Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=3900 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size
Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=3988 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size
Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4076 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size
Apr 28 16:04:59 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4164 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size
Apr 28 16:05:34 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4340 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size
May 12 13:34:52 strike dovecot: imap(USER4): Error: Log synchronization error at seq=2,offset=240 for /home/USER4/mail/.imap/Junk/dovecot.index: Extension header update points outside header size
May 12 21:59:29 strike dovecot: imap(USER5): Error: Log synchronization error at seq=1,offset=30264 for /home/USER5/mail/.imap/virus/dovecot.index: Extension header update points outside header size
-------------------- 8< --------------------



> -------------------- 8< --------------------
> # 2.2.12: /etc/dovecot/dovecot.conf
> # OS: Linux 2.6.32-431.3.1.el6.x86_64 x86_64 CentOS release 6.5 (Final)
> auth_mechanisms = plain login
> auth_verbose = yes
> default_vsz_limit = 512 M
> first_valid_uid = 100
> imap_client_workarounds = tb-extra-mailbox-sep
> login_trusted_networks = 172.23.60.0/24
> mail_location = mbox:~/mail:INBOX=/var/mail/%u
> mail_plugins = " mail_log notify"
> mail_privileged_group = mail
> 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 ihave
> mbox_write_locks = fcntl
> namespace inbox {
>   inbox = yes
>   location = mbox:~/mail:INBOX=/var/mail/%u
>   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 =
>   separator = /
>   type = private
> }
> passdb {
>   driver = pam
> }
> plugin {
>   mail_log_events = delete undelete expunge copy mailbox_delete
> mailbox_rename
>   mail_log_fields = uid box msgid size
> }
> protocols = imap pop3
> service auth {
>   unix_listener /var/spool/postfix/private/auth {
>     group = postfix
>     mode = 0666
>     user = postfix
>   }
> }
> service imap-postlogin {
>   executable = script-login -d /usr/local/sbin/dovecot-post-login.pl
> }
> service imap {
>   executable = imap imap-postlogin
> }
> ssl = required
> ssl_cert = </etc/pki/dovecot/certs/dovecot.pem
> ssl_key = </etc/pki/dovecot/private/dovecot.pem
> userdb {
>   driver = passwd
> }
> -------------------- 8< --------------------
> 
> 
> 


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



More information about the dovecot mailing list