zlib - some emails maybe double or partial gzipped

Sat Jan 5 17:55:49 EET 2019

Hi,

I found these in my logs:

   Jan  5 15:58:56 mail dovecot: imap-login: Login: user=<xy at z.com>, method=PLAIN, rip=1.2.3.4, lip=2.3.4.5, mpid=5852, TLS, session=<K2oaPLd+885fWs6U>
   Jan  5 15:58:56 mail dovecot: imap-login: Login: user=<xy at z.com>, method=PLAIN, rip=1.2.3.4, lip=2.3.4.5, mpid=5854, TLS, session=<uxAjPLd+ys5fWs6U>
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Maildir filename has wrong S value, renamed the file from /var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=17247,W=17549:2,Sab,Z to /var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=4172:2,Sab,Z
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Corrupted index cache file /var/vmail/mailboxes/<xy at z.com>/mail/Sent/dovecot.index.cache: Broken physical size for mail UID 99 in mailbox Sent: read(zlib(/var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=17247,W=17549:2,Sab,Z)) failed: Cached message size larger than expected (17247 > 4268, box=Sent, UID=99)
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Panic: file istream.c: line 175 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip)
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95e92) [0x7f5068d3ee92] -> /usr/lib/dovecot/libdovecot.so.0(+0x95f8d) [0x7f5068d3ef8d] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f5068cd4a91] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x290) [0x7f5068d49f20] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7f5068d4a72d] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header_next+0x72) [0x7f5068d25d12] -> /usr/lib/dovecot/libdovecot.so.0(+0x76fd1) [0x7f5068d1ffd1] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x53) [0x7f5068d49ce3] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7f5068d4a72d] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header_next+0x72) [0x7f5068d25d12] -> /usr/lib/dovecot/libdovecot.so.0(+0x76fd1) [0x7f5068d1ffd1] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x53) [0x7f5068d49ce3] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7f5068d4a72d] -> /usr/lib/dovecot/libdovecot.so.0(message_get_header_size+0x74) [0x7f5068d29904] -> /usr/lib/dovecot/libdovecot-storage.so.0(imap_msgpart_open+0x32f) [0x7f50690b52ef] -> dovecot/imap(+0x1ebbc) [0x556dd2cd7bbc] -> dovecot/imap(+0x1cfb6) [0x556dd2cd5fb6] -> dovecot/imap(imap_fetch_more+0x39) [0x556dd2cd70e9] -> dovecot/imap(cmd_fetch+0x33b) [0x556dd2cc8d9b] -> dovecot/imap(command_exec+0xa5) [0x556dd2cd4735] -> dovecot/imap(+0x199c2) [0x556dd2cd29c2] -> dovecot/imap(+0x19a4c) [0x556dd2cd2a4c] -> dovecot/imap(client_handle_input+0x1b5) [0x556dd2cd2e55] -> dovecot/imap(client_input+0x86) [0x556dd2cd33c6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52) [0x7f5068d539f2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109) [0x7f5068d55029] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c) [0x7f5068d53a8c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f5068d53c38]
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Fatal: master: service(imap): child 5852 killed with signal 6 (core dumps disabled)
   # and again:
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Maildir filename has wrong S value, renamed the file from /var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=4172:2,Sab,Z to /var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=4268:2,Sab,Z
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Corrupted index cache file /var/vmail/mailboxes/<xy at z.com>/mail/Sent/dovecot.index.cache: Broken physical size for mail UID 254 in mailbox Sent: read(zlib(/var/vmail/mailboxes/<xy at z.com>/mail/Sent/cur/1537260554.M80670P8164.mail,S=4172:2,Sab,Z)) failed: Cached message size smaller than expected (4172 < 4268, box=Sent, UID=254)
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Panic: file istream.c: line 212 (i_stream_read): assertion failed: (!i_stream_is_buffer_invalid(_stream))
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95e92) [0x7f1dd9f6be92] -> /usr/lib/dovecot/libdovecot.so.0(+0x95f8d) [0x7f1dd9f6bf8d] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f1dd9f01a91] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x190) [0x7f1dd9f76e20] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7f1dd9f7772d] -> /usr/lib/dovecot/libdovecot.so.0(message_get_header_size+0x74) [0x7f1dd9f56904] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_init_stream+0x388) [0x7f1dda2a7538] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x66fc0) [0x7f1dda25efc0] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_get_stream_because+0x5d) [0x7f1dda22ee1d] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x66d87) [0x7f1dda25ed87] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_get_virtual_size+0x33) [0x7f1dda22ea83] -> dovecot/imap(+0x1eae3) [0x5595eb2dfae3] -> dovecot/imap(+0x1cfb6) [0x5595eb2ddfb6] -> dovecot/imap(imap_fetch_more+0x39) [0x5595eb2df0e9] -> dovecot/imap(cmd_fetch+0x33b) [0x5595eb2d0d9b] -> dovecot/imap(command_exec+0xa5) [0x5595eb2dc735] -> dovecot/imap(+0x199c2) [0x5595eb2da9c2] -> dovecot/imap(+0x19a4c) [0x5595eb2daa4c] -> dovecot/imap(client_handle_input+0x1b5) [0x5595eb2dae55] -> dovecot/imap(client_input+0x86) [0x5595eb2db3c6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52) [0x7f1dd9f809f2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109) [0x7f1dd9f82029] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c) [0x7f1dd9f80a8c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f1dd9f80c38] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f1dd9f07fd3] -> dovecot/imap(main+0x328) [0x5595eb2cde68] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f1dd9b572e1] -> dovecot/imap(_start+0x2a) [0x5595eb2cdfea]
   Jan  5 15:58:56 mail dovecot: imap(<xy at z.com>): Fatal: master: service(imap): child 5854 killed with signal 6 (core dumps disabled)

Trying to read them with zcat they turned out to be binary. I figured out they might accidentally be compressed twice - they are.

How could this happen?

I used this script: dovecot-maildir-compress.sh (https://gist.github.com/cviebrock/e37f80a3223dfee19051c936c5ebe509),
which appends an additional flag 'Z' after processing/conmpressong the mail and only compresses those without the flag:

         > find=$(find "$maildir" -type f -name "*,S=*" -mtime +30 ! -name "*,*:2,*,*Z*" -printf "%f\n")
               ...               > if echo $flags | grep ',';
>             then
>                 newname=$filename"Z"
>             else
>                 newname=$filename",Z"

which is actually neat. 

Now two possible things:

(1) I am not quite sure yet but my best guess is that moving messages from one folder to another
    (via mail client) the message looses it's 'Z' flag.

(2) compressing might have failed to rename but successfully compressed the file and the another
    consecutive run of the script compressed the file again.

How could I recursively 

   (a)  check each maildir file if e.g. the output of(zcat $file | zcat) is ASCII or !binary

   (b) find all mails which are compressed - i.e. valid gzip - but miss the 'Z' flag ?

   (c) find all mails that are valid gzip but dont contain ASCII if / dont uncompress to mail ?

There are backups in place for all files I get a error for, but I want to recursively fix the problem.

Any hint?

Thanks in advance!
-M
-- 
info at awib.it