[IMAP][Maildir] - Dovecot index gets corrupted, when using maildir as mailbox format and Thunderbird as mail client

If you spin up the test environment with dovecot_mailbox_type: maildir as mailbox format and use it with Thunderbird, the dovecot index gets corrupted from time to time.

Content of /var/log/syslog:

Aug  4 09:55:15 trees postfix/smtpd[4619]: connect from unknown[192.168.22.1]
Aug  4 09:55:15 trees postfix/smtpd[4619]: 510AA60F8D: client=unknown[192.168.22.1], sasl_method=PLAIN, sasl_username=treesenabled@trees.testing
Aug  4 09:55:15 trees postfix/cleanup[4638]: 510AA60F8D: message-id=<4ae8ea2c-17ac-37d5-9b9e-b32c6edc777a@trees.testing>
Aug  4 09:55:15 trees postfix/qmgr[10750]: 510AA60F8D: from=<treesenabled@trees.testing>, size=663, nrcpt=1 (queue active)
Aug  4 09:55:15 trees postfix/smtpd[4619]: disconnect from unknown[192.168.22.1] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8
Aug  4 09:55:15 trees dovecot: lda(treesenabled@trees.testing): Debug: trees plugin initialized
Aug  4 09:55:15 trees dovecot: lda(treesenabled@trees.testing): msgid=<4ae8ea2c-17ac-37d5-9b9e-b32c6edc777a@trees.testing>: saved mail to INBOX
Aug  4 09:55:15 trees postfix/pipe[4640]: 510AA60F8D: to=<treesenabled@trees.testing>, relay=dovecot, delay=0.08, delays=0.03/0.02/0/0.03, dsn=2.0.0, status=sent (delivered via dovecot service)
Aug  4 09:55:15 trees postfix/qmgr[10750]: 510AA60F8D: removed
Aug  4 09:55:15 trees dovecot: imap-login: Login: user=<treesenabled@trees.testing>, method=PLAIN, rip=192.168.22.1, lip=192.168.22.77, mpid=4643, TLS, session=<w0OCCplyhLLAqBYB>
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Debug: trees plugin initialized
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Connection closed in=506 out=495
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Error: Maildir filename has wrong S value, renamed the file from /var/vmail/trees.testing/treesenabled/Maildir/cur/1533376515.M379290P4641.trees,S=1456,W=748:2, to /var/vmail/trees.testing/treesenabled/Maildir/cur/1533376515.M379290P4641.trees,S=783:2,
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Error: Corrupted index cache file /var/vmail/trees.testing/treesenabled/Maildir/dovecot.index.cache: Broken physical size for mail UID 1 in mailbox INBOX: read(/var/vmail/trees.testing/treesenabled/Maildir/cur/1533376515.M379290P4641.trees,S=1456,W=748:2,) failed: Cached message size larger than expected (1456 > 728, box=INBOX, UID=1, cached Message-Id=<4ae8ea2c-17ac-37d5-9b9e-b32c6edc777a@trees.testing>)
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Panic: file istream.c: line 175 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip)
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95e92) [0x7fa88e2afe92] -> /usr/lib/dovecot/libdovecot.so.0(+0x95f8d) [0x7fa88e2aff8d] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7fa88e245a91] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x290) [0x7fa88e2baf20] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7fa88e2bb72d] -> /usr/lib/dovecot/libdovecot.so.0(message_get_body_size+0xfd) [0x7fa88e29ab6d] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_init_stream+0x220) [0x7fa88e5eb3d0] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x66fc0) [0x7fa88e5a2fc0] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_get_stream_because+0x5d) [0x7fa88e572e1d] -> /usr/lib/dovecot/libdovecot-storage.so.0(imap_msgpart_open+0x536) [0x7fa88e6264f6] -> dovecot-trees.testing/imap(+0x1ebbc) [0x559b794f1bbc] -> dovecot-trees.testing/imap(+0x1cfb6) [0x559b794effb6] -> dovecot-trees.testing/imap(imap_fetch_more+0x39) [0x559b794f10e9] -> dovecot-trees.testing/imap(cmd_fetch+0x33b) [0x559b794e2d9b] -> dovecot-trees.testing/imap(command_exec+0xa5) [0x559b794ee735] -> dovecot-trees.testing/imap(+0x199c2) [0x559b794ec9c2] -> dovecot-trees.testing/imap(+0x19a4c) [0x559b794eca4c] -> dovecot-trees.testing/imap(client_handle_input+0x1b5) [0x559b794ece55] -> dovecot-trees.testing/imap(client_input+0x86) [0x559b794ed3c6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52) [0x7fa88e2c49f2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109) [0x7fa88e2c6029] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c) [0x7fa88e2c4a8c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7fa88e2c4c38] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fa88e24bfd3] -> dovecot-trees.testing/imap(main+0x328) [0x559b794dfe68] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7fa88de9b2e1] -> dovecot-trees.testing/imap(_start+0x2a) [0x559b794dffea]
Aug  4 09:55:15 trees dovecot: imap(treesenabled@trees.testing): Fatal: master: service(imap): child 4633 killed with signal 6 (core dumps disabled)
Aug  4 09:55:16 trees dovecot: imap-login: Login: user=<treesenabled@trees.testing>, method=PLAIN, rip=192.168.22.1, lip=192.168.22.77, mpid=4645, TLS, session=<9lOLCplyhrLAqBYB>

This leads to a reoccurring crash of dovecot, which can only be fixed with expunging all mails from the inbox or deleting the mail account.

root@trees:~# sudo rm -r /var/vmail/trees.testing/treesenabled/
root@trees:~# sudo service dovecot restart

So I started some digging and send some mails.

#!/bin/bash
# Tested using bash version 4.1.5
for ((i=1;i<=10000;i++)); 
do 
   # your-unix-command-here
   echo "That's a trees encryption test NR $i" | mail -s "A trees test $i" treesenabled@trees.testing
done

It's no problem to send 10000 mails to the user, without any corruption occurring, when you are not receiving your mails with Thunderbird at the same time.

But if you sending those mails and access/receive those mails with Thunderbird at the same time, you ran into this cache corruption.

Aug  4 11:12:19 trees dovecot: imap(treesenabled@trees.testing): Error: Corrupted index cache file /var/vmail/trees.testing/treesenabled/Maildir/dovecot.index.cache: Broken physical size for mail UID 10166 in mailbox INBOX: read(/var/vmail/trees.testing/treesenabled/Maildir/cur/1533381139.M373613P6934.trees,S=888,W=456:2,) failed: Cached message size larger than expected (888 > 444, box=INBOX, UID=10166, cached Message-Id=<20180804111219.5745F60E7C@trees.testing>)
Aug  4 11:12:20 trees dovecot: imap(treesenabled@trees.testing): Error: Corrupted index cache file /var/vmail/trees.testing/treesenabled/Maildir/dovecot.index.cache: Broken physical size for mail UID 10189 in mailbox INBOX: read(/var/vmail/trees.testing/treesenabled/Maildir/cur/1533381139.M373613P6934.trees,S=499:2,) failed: Cached message size larger than expected (499 > 444, box=INBOX, UID=10189)

Do you have any ideas, why that happens?

Appendix

# 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.16 (fed8554)
# OS: Linux 4.9.0-6-amd64 x86_64 Debian 9.4 ext4
auth_mechanisms = plain login
instance_name = trees.testing
login_greeting = trees.testing ready.
mail_gid = 5000
mail_location = maildir:/var/vmail/%Ld/%Ln/Maildir
mail_plugins = " quota trees"
mail_uid = 5000
mailbox_list_index = yes
namespace inbox {
  inbox = yes
  location = 
  mailbox Drafts {
    auto = subscribe
    special_use = \Drafts
  }
  mailbox Junk {
    auto = subscribe
    autoexpunge = 30 days
    special_use = \Junk
  }
  mailbox Sent {
    auto = subscribe
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    auto = subscribe
    autoexpunge = 30 days
    special_use = \Trash
  }
  prefix = 
}
passdb {
  args = /etc/dovecot/dovecot-sql.conf.ext
  driver = sql
}
protocols = " imap pop3"
service auth {
  unix_listener /var/spool/postfix/private/auth {
    mode = 0666
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0660
  }
}
service imap-login {
  inet_listener imap {
    port = 143
  }
  inet_listener imaps {
    port = 993
    ssl = yes
  }
  process_min_avail = 4
}
service imap {
  executable = imap
}
service pop3 {
  executable = pop3
}
ssl = required
ssl_cert = </etc/ssl/certs/ssl-cert-snakeoil.pem
ssl_cipher_list = ALL:!LOW:!RC4:!EXP:!aNULL
ssl_dh_parameters_length = 2048
ssl_key =  # hidden, use -P to show it
ssl_prefer_server_ciphers = yes
userdb {
  driver = prefetch
}
userdb {
  args = /etc/dovecot/dovecot-sql.conf.ext
  driver = sql
}