Corrupted sizes in cache once again

[Tim Evers]

I would like to add some more observations:


I hav another mailbox with one mail's size being saved wrong in the 
cache file:


doveadm dump:

RECORD: seq=40, uid=1202, flags=0x00
  - ext 5 cache     :       8504 (38210000)
  - ext 6 vsize     :     145625 (d9380200)
                    : vsize         = 5166845802713
                    : highest_uid   = 0
                    : message_count = 8716
  - cache offset=8504 size=212, prev_offset = 0
     - hdr.From: 42: From: [redacted]
     - hdr.Message-ID: 45: Message-ID:  [redacted]
     - hdr.Subject: 44: Subject:  [redacted]
     - flags: (20000000)

RECORD: seq=41, uid=1203, flags=0x00
  - ext 5 cache     :       8716 (0c220000)
  - ext 6 vsize     :     105141 (b59a0100)
                    : vsize         = 105141
                    : highest_uid   = 0
                    : message_count = 0
  - cache offset=8716 size=280, prev_offset = 0
     - hdr.From: 104: From:  [redacted]
     - hdr.Message-ID: 108: Message-ID:  [redacted]
     - hdr.Subject: 105: Subject:  [redacted]
     - flags: (20000000)

The message with seq=40 is the mail dovecot complains about:


Error: Corrupted record in index cache file 
/[redacted]/Maildir/dovecot.index.cache: UID 1202: Broken physical size 
in mailbox INBOX: 
read(zlib(/[redacted]/Maildir/new/1675176154.M829333P14495.node2,S=232816,W=236045)) 
failed: Cached message size smaller than expected (145082 < 146788, 
box=INBOX, UID=1202)


Size on disk is 145082


Size after decompression is 232816 (as expected)


Message with seq=41 is correct with both vsize in cache and decompressed 
size being equal.


Before the POP3 access that produced the error both mails were only ever 
touched by the dovecot lmtp delivery process.


Am 01.02.23 um 14:13 schrieb Tim Evers:
> Hi,
>
> I run a fairly large Dovecot Installation (around 100k mailboxes) on 
> several servers.
>
> gzip compression is on.
>
> Every once in a while I get the dreaded "cache corruption" messages in 
> the log:
>
> Error: Corrupted record in index cache file 
> /[redacted]/Maildir/dovecot.index.cache: UID 3868: Broken physical 
> size in mailbox INBOX: 
> read(zlib(/[redacted]/Maildir/cur/1674129792.M797543P21755.node2,S=8099,W=8276:2,)) 
> failed: Cached message size smaller than expected (2877 < 8099, 
> box=INBOX, UID=3868)
>
> Error: Corrupted record in index cache file 
> /[redacted]/Maildir/dovecot.index.cache: UID 3875: Broken physical 
> size in mailbox INBOX: 
> read(zlib(/[redacted]/Maildir/cur/1674212201.M985809P29112.node2,S=13907,W=14121:2,)) 
> failed: Cached message size smaller than expected (5533 < 8192, 
> box=INBOX, UID=3875)
>
> The first entry shows 2877 (size on disk) vs. 8099 (real size 
> unzipped, also in the filename: S=8099).
>
> The second entry shows 5533 (size on disk) vs. 8192 - this is not 
> correct in any way. Size on disk is 13907 as noted in the filename.
>
> Both mails were delivered trough LMTP and retrieved by the POP3 service.
>
> Anyone with an idea what might be happening here? I've read all 
> available info in the doc and in the previous discussions / bug 
> reports, but nothing seems to match my case. And where does that 8192 
> come from - it looks suspicious?
>
> Version is 2.3.7.2 (Ubuntu 20.04)
>
> doveconf -n excerpt:
>
> protocol lmtp {
>   mail_plugins = " old_stats mail_log notify zlib sieve quota"
> }
> protocol imap {
>   mail_max_userip_connections = 50
>   mail_plugins = " old_stats mail_log notify zlib imap_old_stats quota 
> imap_quota imap_sieve"
> }
> protocol pop3 {
>   mail_max_userip_connections = 50
>   mail_plugins = " old_stats mail_log notify zlib"
> }
>
> Tim
>