cyrus.cache causes IOERROR: offset greater than cache size

[Дилян Палаузов]

Hello,

it turned out that after emitting the messages below, cyrus.cache (3.0) was not self-repaired and stayed bogus.  In
fact, reconstruct also does not repair cyrus.cache, unless cyrus.index is deleted.  If cyrus.index is present and
cyrus.cache is missing, reconstruct creates a four-bytes large file.

Greetings
  Дилян

On Mon, 2019-12-02 at 12:46 +0000, Дилян Палаузов wrote:
> Hello,
> 
> sometimes I get in the logs these messages:
> 
> Dec 01 01:30:50 mail cyrus/cyr_expire[13952]: IOERROR: offset greater than cache size 5243456 2288(0)
> Dec 01 01:30:50 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 40568 (System I/O error)
> Dec 01 01:30:54 mail cyrus/cyr_expire[13952]: IOERROR: offset greater than cache size 5244620 2288(0)
> Dec 01 01:30:54 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 40569 (System I/O error)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: offset greater than cache size 5247552 2288(0)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 40571 (System I/O error)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 15463 (Mailbox format
> corruption detected)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: cache entry truncated 1072 1835101728 2288(0)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 15464 (System I/O error)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: cache entry truncated 2080 1131376244 2288(0)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 15465 (System I/O error)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: offset greater than cache size (priority)3136 2288(0)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: invalid cache record for user.u1 uid 15466 (System I/O error)
> Dec 01 01:30:55 mail cyrus/cyr_expire[13952]: IOERROR: offset greater than cache size (priority)3976 2288(0)
> 
> Often it is connected to cyr_exipre, but not always. It can be also lmtpd.
> 
> When a cyrus.cache inconsistency is detected, the cyrus.cache is rebuild. This means reading a lot of files from the
> disk.  During the reconstruction some locks are active, so effectively a lot of processes (lmtpd, imapd, httpd) are
> started and all of them wait for the lock to be released.  This cache rebuild happens sometimes (perceived) very often. 
> The problem is that on slow hard disks this repack operation can take hours and cyr_expire runs for hours.
> 
> My reading of the code is that new records are only appended to cyrus.cache and there is some lock ensuring the
> consistency of the append operation.
> 
> I have not invested that much time in reading the code.  How is expunging supposed to happen in regards of cyrus.cache? 
> Is the on unlink()ing any message the cyrus.cache always supposed to be repacked or where is the code for removing
> entries from cyrus.cache?  How can I debug the cause of the invalid cache record?  
> 
> I assume that the cached records are kept, until the corresponding message file is removed from the disk.
> 
> The cyr_expire output also contains:
> 
> Dec 01 01:37:37 mail cyrus/cyr_expire[13952]: IOERROR: conversations_audit on load: /var/imap//user/s/s2.conversations
> B25572d90ed3363c1
>  0 (713535 1 0 0 () ((18 713534 1 1 0)) () PleaseconfirmyourNNNNregistrationnow. 0 ())
> 
> What am I supposed to do with this message?
> 
> Regards
>   Дилян
>