IMAP COPY creates invalid index data with zlib and mail_log plugins enabled but zlib_save off

[Robert L Mathews]

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/