dovecot - Jul 2014 - Panic: file istream.c: line 167 with 2.2.13 + istream.c/.h from dovecot-2-2-dffc6dd2be0d

Hi,

Getting following panics with traces:
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Cached message 
size smaller than expected (1782 < 1872)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Maildir filename 
has wrong S value, renamed the file from 
/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S 
to /path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1872:2,S
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Corrupted index 
cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical 
size for mail UID 5758
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: 
read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) 
failed: Invalid argument
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: 
read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) 
failed: Invalid argument (uid=5758)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Cached message 
size smaller than expected (1781 < 1869)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Maildir filename 
has wrong S value, renamed the file from 
/path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S 
to /path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1869:2,S
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Corrupted index 
cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical 
size for mail UID 5767
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: 
read(/path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S) 
failed: Invalid argument
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: 
read(/path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S) 
failed: Invalid argument (uid=5767)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Cached message 
size smaller than expected (9252 < 9346)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Maildir filename 
has wrong S value, renamed the file from 
/path/cencored/Maildir/cur/1205131753.12346.host.cencored.fi,S=9252:2,RS 
to /path/cencored/Maildir/cur/1205131753.12346.host.cencored.fi,S=9346:2,RS
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Corrupted index 
cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical 
size for mail UID 6296
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Panic: file istream.c: 
line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - 
_stream->skip)
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Raw backtrace: 
/usr/lib/dovecot/libdovecot.so.0 [0x575c1f] -> 
/usr/lib/dovecot/libdovecot.so.0 [0x575c9d] -> 
/usr/lib/dovecot/libdovecot.so.0 [0x575514] -> 
/usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57f99b] -> 
/usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x2b) [0x57fbfb] -> 
/usr/lib/dovecot/libdovecot.so.0 [0x565b5e] -> 
/usr/lib/dovecot/libdovecot.so.0 [0x567469] -> 
/usr/lib/dovecot/libdovecot.so.0(message_parser_parse_next_block+0x43) 
[0x565cd3] -> 
/usr/lib/dovecot/libdovecot.so.0(message_parser_parse_body+0x2c) 
[0x565e4c] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x944dd2] -> 
/usr/lib/dovecot/libdovecot-storage.so.0(index_mail_get_parts+0x6a) 
[0x945c7a] -> 
/usr/lib/dovecot/libdovecot-storage.so.0(mail_get_parts+0x16) [0x91ad76] 
-> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94aa7c] -> 
/usr/lib/dovecot/libdovecot-storage.so.0 [0x94ba89] -> 
/usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblo
Jul  6 08:11:52 dovecot: imap(user at domain.tld): Fatal: master: 
service(imap): child 31268 killed with signal 6 (core dumps disabled)

These can of course be fixed with maildir-size-fix.pl and deleting 
dovecot index files, but there are thousands like these. Dovecot 1.2 
didn't have any issues with these old maildirs transfered over from 
courierimap.

Best Regards,
Toni Mattila

On 6.7.2014, at 12.07, Toni Mattila <toni at solu.fi> wrote:
> Getting following panics with traces:
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Cached message
size smaller than expected (1782 < 1872)
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Maildir filename
has wrong S value, renamed the file from
/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S to
/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1872:2,S
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error: Corrupted index
cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical size for
mail UID 5758
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error:
read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S)
failed: Invalid argument
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Error:
read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S)
failed: Invalid argument (uid=5758)
This is intended.
> Jul  6 08:11:52 dovecot: imap(user at domain.tld): Panic: file istream.c:
line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos -
_stream->skip)
This isn't intended, but I can't seem to be able to reproduce the crash.
What's your doveconf -n output?
> These can of course be fixed with maildir-size-fix.pl and deleting dovecot
index files, but there are thousands like these. Dovecot 1.2 didn't have any
issues with these old maildirs transfered over from courierimap.
maildir_broken_filename_sizes=yes restores the old behavior.