dovecot - Nov 2015 - IMAP COPY creates invalid index data with zlib and mail_log plugins enabled but zlib_save off

I've noticed that maildir IMAP COPY commands can generate invalid
dovecot.index entries when all seven of the following are true:

- The zlib plugin is enabled;
- The zlib_save/zlib_save_level options are NOT enabled;
- The source message being copied is compressed;
- The mail_log plugin is logging "copy" events;
- The mail_log_fields setting includes at least one message header;
- The destination mailbox folder has an index file that is recording the
logged headers;
- The source mailbox folder does NOT have an index file recording the
logged headers.

In this situation, copying a message results in an index entry in the
destination that has all the headers blank, like this:

RECORD: seq=5, uid=182415, flags=0x08 (Seen)
 - ext 1 modseq    :          3 (0300000000000000)
 - ext 2 cache     :       2352 (30090000)
 - cache offset=2352 size=120, prev_offset = 0
    - hdr.FROM:
    - hdr.MESSAGE-ID:
    - hdr.SUBJECT:
    - hdr.DATE:
    - hdr.BCC:
    - hdr.CC:
    - hdr.CONTENT-TYPE:
    - hdr.IN-REPLY-TO:
    - hdr.NEWSGROUPS:
    - hdr.PRIORITY:
    - hdr.REFERENCES:
    - hdr.REPLY-TO:
    - hdr.TO:
    - hdr.X-PRIORITY:

For these copies, the mail_log plugin records blank header data in the
log, too, like this (despite the message having a valid message-ID,
from, and subject):

Oct 29 21:11:42 wheezy dovecot: imap[31763]: user=<1 at example.com>
ip=192.168.0.4 session=RV/MmUojyADAqAAE copy from INBOX.Saved:
box=INBOX.Trash, uid=182412, msgid=, size=1357, vsize=1392, from=,
subject=, flags=(\Seen)

I've found this occurs in at least Dovecot 2.1.7, 2.2.13, and 2.2.18
(all packaged Debian versions).

Changing any of the seven things I mentioned above fixes it. I've tried
to find the code that causes this, but not yet been successful. My
theory is that when the mail_log plugin calls mail_get_first_header(),
and there's no index header record to read it from, it looks at the real
message on disk. Perhaps it somehow operates on a compressed copy of the
message although it expects uncompressed plaintext, so it doesn't find
any of the headers. The "missing" headers then get cached to the
destination index file as a side-effect.

The copied maildir message itself is fine, by the way. It's an
identical, still-compressed copy of the original message. And deleting
the destination "dovecot.index*" files that contain the bad data
causes
Dovecot to rebuild the index with the correct header data.

It's unusual to use the zlib plugin without the
zlib_save/zlib_save_level options enabled, of course. That's probably
why (as far as I can tell) there have been no reports of this before. I
noticed it only because I was testing a small amount of manual mail
compression before deploying it for all mail.

Here's the "doveconf -n" of a system in the "has the
problem" state:

# 2.2.18: /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.8 (0c4ae064f307+)
# OS: Linux 3.2.0-4-686-pae i686 Debian stretch/sid
auth_mechanisms = plain login
auth_username_format auth_verbose = yes
auth_verbose_passwords = sha1
default_vsz_limit = 1 G
disable_plaintext_auth = no
lda_mailbox_autosubscribe = yes
listen = *
log_timestamp = "%Y-%m-%d %H:%M:%S "
login_log_format_elements = user=<%u> pid=[%{mail_pid}] method=%m rip=%r
lip=%l %c
mail_fsync = never
mail_location = maildir:~/
mail_log_prefix = "%s[%{pid}]: user=<%u> ip=%{rip} session=%{session}
"
mail_max_userip_connections = 100
mail_plugins = mail_log notify zlib
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto envelope encoded-character
vacation subaddress comparator-i;ascii-numeric relational regex
imap4flags copy include variables body enotify environment mailbox date
index ihave duplicate spamtest spamtestplus
namespace {
  inbox = yes
  location   prefix = INBOX.
  separator = .
  type = private
}
namespace {
  hidden = yes
  inbox = no
  list = no
  location   prefix   separator = .
  type = private
}
passdb {
  args = /etc/dovecot/dovecot.users
  driver = passwd-file
}
plugin {
  fts = lucene
  fts_lucene = whitespace_chars=@.
  mail_log_events = copy delete undelete expunge mailbox_delete
mailbox_rename flag_change save mailbox_create
  mail_log_fields = vsize size flags box uid box msgid size flags vsize
from subject
  sieve = %h/mailbox.sieve
  sieve_after = %h/../../domain-after.sieve
  sieve_before = %h/../../domain-before.sieve
  sieve_dir = %h/sieve
  sieve_extensions = -reject +spamtest +spamtestplus
  sieve_global_dir = %h/../../sieve-global-include-scripts
  sieve_spamtest_max_value = 7
  sieve_spamtest_status_header = X-Spam-Level
  sieve_spamtest_status_type = strlen
}
protocols = pop3 imap lmtp sieve
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
}
service imap-login {
  process_min_avail = 8
  service_count = 0
}
service imap {
  process_limit = 2000
}
service lmtp {
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    mode = 0660
    user = postfix
  }
}
service pop3-login {
  process_min_avail = 8
  service_count = 0
}
service pop3 {
  process_limit = 2000
}
ssl = no
userdb {
  args = /etc/dovecot/dovecot.users
  driver = passwd-file
}
verbose_proctitle = yes
protocol imap {
  imap_client_workarounds = delay-newmail
  imap_logout_format = %i bytes in, %o bytes out
}
protocol pop3 {
  pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
  pop3_logout_format = ; %i bytes in, %o bytes out, %t top (%p bytes),
%r retr (%b bytes), %d of %m deleted, mailbox size %s bytes
  pop3_uidl_format = UID%u-%v
}
protocol lda {
  mail_fsync = optimized
  mail_plugins = mail_log notify zlib sieve
}
protocol lmtp {
  mail_fsync = optimized
  mail_plugins = mail_log notify zlib sieve
}

-- 
Robert L Mathews, Tiger Technologies, http://www.tigertech.net/

On 10/30/15 3:06 PM, Robert L Mathews wrote:
> I've noticed that maildir IMAP COPY commands can generate invalid
> dovecot.index entries when all seven of the following are true:
As a followup to my own post, I believe I've tracked this problem down
to this code at lines 119-124 of /src/plugins/zlib/zlib-plugin.c:

 /* don't uncompress input when we are reading a mail that we're just
    in the middle of saving, and we didn't do the compression ourself.
    in such situation we're probably checking if the user-given input
    looks compressed */
 if (_mail->saving && zuser->save_handler == NULL)
         return zmail->super.istream_opened(_mail, stream);

When these lines are removed, the problem no longer happens.

I'm guessing that an IMAP COPY with the seven circumstances I mentioned
matches "we are reading a mail that we're just in the middle of saving,
and we didn't do the compression ourself". But the mail apparently does
need decompressing in this situation.

It seems odd for the code to not simply decompress the mail in all
cases. But I'm not sure what other code relies on this check, so I have
no idea whether removing these lines might cause problems.

-- 
Robert L Mathews, Tiger Technologies, http://www.tigertech.net/

> On 02 Nov 2015, at 22:12, Robert L Mathews <lists at tigertech.com>
wrote:
> 
> On 10/30/15 3:06 PM, Robert L Mathews wrote:
> 
>> I've noticed that maildir IMAP COPY commands can generate invalid
>> dovecot.index entries when all seven of the following are true:
> 
> As a followup to my own post, I believe I've tracked this problem down
> to this code at lines 119-124 of /src/plugins/zlib/zlib-plugin.c:
> 
> /* don't uncompress input when we are reading a mail that we're
just
>    in the middle of saving, and we didn't do the compression ourself.
>    in such situation we're probably checking if the user-given input
>    looks compressed */
> if (_mail->saving && zuser->save_handler == NULL)
>         return zmail->super.istream_opened(_mail, stream);
> 
> When these lines are removed, the problem no longer happens.
> 
> I'm guessing that an IMAP COPY with the seven circumstances I mentioned
> matches "we are reading a mail that we're just in the middle of
saving,
> and we didn't do the compression ourself". But the mail apparently
does
> need decompressing in this situation.
> 
> It seems odd for the code to not simply decompress the mail in all
> cases. But I'm not sure what other code relies on this check, so I have
> no idea whether removing these lines might cause problems.
The check is there to make sure that people can't try to exploit bugs in
compression libraries by uploading something that Dovecot attempts to decompress
later on. So if the input looks compressed it's simply rejected. (If
zlib_save is enabled this isn't a problem, because the compressed-looking
input is compressed again.)

Fixed: http://hg.dovecot.org/dovecot-2.2/rev/574c1e5b3d90