Hi Dovecot folks,
I recently reported this bug in Debian (https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=939442) after a stretch -> buster upgrade, however since I can reproduce it using the latest 2.4 from git I thought perhaps I ought to take it straight upstream.
Here's the text I provided Debian about the issue, and below that I've included a syslog snip showing the same issue in a fresh build of git master as well.
mail_filter_out seems to fully panic (backtrace below), whereas mail_filter is just behaving oddly.
Thanks :)
Package: dovecot-core Version: 2.3.4.1-5+deb10u1 Severity: important
Hi Dovecot maintainers,
After upgrading from the latest stretch version of dovecot-core (2.2.27-3+deb9u5) to buster (2.3.4.1-5+deb10u1) the "mail filter" interface seems to have broken. This problem is also present in the sid version (2.3.7.2-1).
Mail filter is used to run the content of messages being stored or retrieved through an arbitrary process. The interface used for the external process is described here: https://wiki.dovecot.org/Plugins/MailFilter
It is expected that the process will be called with the arguments specified in the configuration then supplied a message body on stdin, however since upgrading it seems that the arguments are not being correctly passed, instead being all jammed in to $1 and separated by tabs, rather than expanded in to argv. Even stranger the first few lines of the body of the message appear in argv rather than in stdin...
These reproduction steps were carried out on a fresh install of Debian Buster with the "dovecot-core" package installed initially from stretch then upgraded to the buster version, however this behaviour has also been observed on stretch systems after upgrading to buster.
To reproduce, drop this minimalised config in to /etc/dovecot/conf.d/repro.conf:
# Minimal maildir setup for LDA first_valid_uid = 0 mail_location = maildir:~/Maildir userdb { driver = static args = allow_all_users=yes uid=mail gid=mail home=/tmp/%u }
# Mail filter configuration mail_plugins = $mail_plugins mail_filter
plugin { mail_filter = mail-filter read %u mail_filter_out = mail-filter write %u }
service mail-filter { executable = script /usr/local/bin/mail-filter.sh user = dovecot unix_listener mail-filter { mode = 0666 } }
And create the example script in /usr/local/bin/mail-filter.sh with executable permissions:
#!/bin/bash
echo "arguments were: $@" 1>&2 tempfile=$(mktemp) cat > "${tempfile}" cat "${tempfile}" rm "${tempfile}"
This script simply logs the arguments it recieves, writes stdin to a file then retrieves it again from the file.
Here's a sample session of me using dovecot-lda to pass a message through this script, then retrieve it again with doveadm:
root@scratch-b6fd8bdd:~# /usr/lib/dovecot/dovecot-lda -d fincham@scratch-b6fd8bdd -f 'Test <scratch-b6fd8bdd>' < /root/test.eml root@scratch-b6fd8bdd:~# doveadm fetch -u 'fincham@scratch-b6fd8bdd' hdr subject Test hdr: To: Test fincham@scratch-b6fd8bdd From: Test fincham@scratch-b6fd8bdd Subject: This is the test e-mail
root@scratch-b6fd8bdd:~# tail /var/log/syslog | grep mail-filter Sep 5 00:07:48 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: write fincham@scratch-b6fd8bdd Sep 5 00:07:50 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: read fincham@scratch-b6fd8bdd
However after upgrading dovecot to the buster version this process no longer works, and the logged argv of the example script is very strange:
root@scratch-b6fd8bdd:~# apt dist-upgrade
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following NEW packages will be installed:
liblua5.3-0 libsodium23 ssl-cert
The following packages will be upgraded:
dovecot-core
[...]
root@scratch-b6fd8bdd:~# /usr/lib/dovecot/dovecot-lda -d fincham@scratch-b6fd8bdd -f scratch-b6fd8bdd < /root/test.eml Aborted root@scratch-b6fd8bdd:~# doveadm fetch -u 'fincham@scratch-b6fd8bdd' hdr subject Test hdr: Hello! doveadm(fincham@scratch-b6fd8bdd): Error: Mailbox INBOX: UID=1: read() failed: Cached message size larger than expected (115 > 7, box=INBOX, UID=1) (read reason=mail stream) doveadm(fincham@scratch-b6fd8bdd): Error: Corrupted record in index cache file /tmp/fincham@scratch-b6fd8bdd/Maildir/dovecot.index.cache: UID 1: Broken physical size in mailbox INBOX: read() failed: Cached message size larger than expected (115 > 7, box=INBOX, UID=1) doveadm(fincham@scratch-b6fd8bdd): Error: read() failed: Cached message size larger than expected (115 > 7, box=INBOX, UID=1) doveadm(fincham@scratch-b6fd8bdd): Error: fetch(hdr) failed for box=INBOX uid=1: read() failed: Cached message size larger than expected (115 > 7, box=INBOX, UID=1) root@scratch-b6fd8bdd:~# tail /var/log/syslog | grep mail-filter Sep 5 00:07:48 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: write fincham@scratch-b6fd8bdd Sep 5 00:07:50 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: read fincham@scratch-b6fd8bdd Sep 5 00:12:11 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: write#011fincham@scratch-b6fd8bdd#011 To: Test fincham@scratch-b6fd8bdd From: Test fincham@scratch-b6fd8bdd Subject: This is the test e-mail Sep 5 00:12:14 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: read#011fincham@scratch-b6fd8bdd#011 To: Test fincham@scratch-b6fd8bdd From: Test fincham@scratch-b6fd8bdd Subject: This is the test e-mail
-- Package-specific info:
dovecot configuration
# 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.4 () # OS: Linux 4.19.0-5-cloud-amd64 x86_64 Debian 10.0 # Hostname: scratch-b6fd8bdd first_valid_uid = 0 mail_location = maildir:~/Maildir mail_plugins = " mail_filter" mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { driver = pam } plugin { mail_filter = mail-filter read %u mail_filter_out = mail-filter write %u } service mail-filter { executable = script /usr/local/bin/mail-filter.sh unix_listener mail-filter { mode = 0666 } user = dovecot } ssl = no userdb { driver = passwd } userdb { args = allow_all_users=yes uid=mail gid=mail home=/tmp/%u driver = static }
-- System Information: Debian Release: 10.0 APT prefers stable-updates APT policy: (500, 'stable-updates'), (500, 'stable') Architecture: amd64 (x86_64)
Kernel: Linux 4.19.0-5-cloud-amd64 (SMP w/2 CPU cores) Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8) Shell: /bin/sh linked to /usr/bin/dash Init: systemd (via /run/systemd/system) LSM: AppArmor: enabled
Versions of packages dovecot-core depends on: ii adduser 3.118 ii libapparmor1 2.13.2-10 ii libbz2-1.0 1.0.6-9.1 ii libc6 2.28-10 ii libexttextcat-2.0-0 3.4.5-1 ii libicu63 63.1-6 ii liblua5.3-0 5.3.3-1.1 ii liblz4-1 1.8.3-1 ii liblzma5 5.2.4-1 ii libpam-runtime 1.3.1-5 ii libpam0g 1.3.1-5 ii libsodium23 1.0.17-1 ii libssl1.1 1.1.1c-1 ii libstemmer0d 0+svn585-1+b2 ii libwrap0 7.6.q-28 ii lsb-base 10.2019051400 ii openssl 1.1.1c-1 ii ssl-cert 1.0.39 ii ucf 3.0038+nmu1 ii zlib1g 1:1.2.11.dfsg-1
dovecot-core recommends no packages.
Versions of packages dovecot-core suggests: pn dovecot-gssapi <none> pn dovecot-imapd <none> pn dovecot-ldap <none> pn dovecot-lmtpd <none> pn dovecot-lucene <none> pn dovecot-managesieved <none> pn dovecot-mysql <none> pn dovecot-pgsql <none> pn dovecot-pop3d <none> pn dovecot-sieve <none> pn dovecot-solr <none> pn dovecot-sqlite <none> pn dovecot-submissiond <none> ii ntp 1:4.2.8p12+dfsg-4
Versions of packages dovecot-core is related to: ii dovecot-core [dovecot-common] 1:2.3.4.1-5+deb10u1 pn dovecot-dev <none> pn dovecot-gssapi <none> pn dovecot-imapd <none> pn dovecot-ldap <none> pn dovecot-lmtpd <none> pn dovecot-managesieved <none> pn dovecot-mysql <none> pn dovecot-pgsql <none> pn dovecot-pop3d <none> pn dovecot-sieve <none> pn dovecot-sqlite <none>
-- no debconf information
And here it is on 2.4 from git:
Sep 5 02:18:10 scratch-b6fd8bdd dovecot: master: Dovecot v2.4.devel () starting up for imap, pop3, lmtp Sep 5 02:18:10 scratch-b6fd8bdd systemd[1]: Started LSB: Dovecot init script. Sep 5 02:18:12 scratch-b6fd8bdd dovecot: mail-filter: Error: arguments were: write#011fincham@scratch-b6fd8bdd#011 To: Test fincham@scratch-b6fd8bdd From: Test fincham@scratch-b6fd8bdd Subject: This is the test e-mail Sep 5 02:18:12 scratch-b6fd8bdd dovecot: lda(fincham@scratch-b6fd8bdd)<4213><94f8BWRwcF11EAAA/w3Ckw>: Panic: file ostream.c: line 201 (o_stream_flush): assertion failed: (stream->stream_errno != 0) Sep 5 02:18:12 scratch-b6fd8bdd dovecot: lda(fincham@scratch-b6fd8bdd)<4213><94f8BWRwcF11EAAA/w3Ckw>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xef5fb) [0x7f85ed0715fb] -> /usr/lib/dovecot/libdovecot.so.0(+0xef661) [0x7f85ed071661] -> /usr/lib/dovecot/libdovecot.so.0(+0x4e808) [0x7f85ecfd0808] -> /usr/lib/dovecot/libdovecot.so.0(+0x52ec1) [0x7f85ecfd4ec1] -> /usr/lib/dovecot/libdovecot-storage.so.0(maildir_save_finish+0x96) [0x7f85ed1b24d6] -> /usr/lib/dovecot/libdovecot-lda.so.0(+0x4395) [0x7f85ed294395] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_save_finish+0x82) [0x7f85ed189e52] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_storage_copy+0xd9) [0x7f85ed17c409] -> /usr/lib/dovecot/libdovecot-storage.so.0(maildir_copy+0x52) [0x7f85ed1aea02] -> /usr/lib/dovecot/libdovecot-lda.so.0(+0x4221) [0x7f85ed294221] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x5c1bc) [0x7f85ed18a1bc] -> /usr/lib/dovecot/libdovecot-lda.so.0(mail_deliver_save+0x1b0) [0x7f85ed295390] -> /usr/lib/dovecot/libdovecot-lda.so.0(mail_deliver+0x2f6) [0x7f85ed295ad6] -> /usr/libexec/dovecot/dovecot-lda(main+0x81b) [0x560cba869f4b] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f85ecdde09b] -> /usr/libexec/dovecot/dovecot-lda(_start+0x2a) [0x560cba86a65a]