Hi,
We run dovecot + postfix + pigeonhole. Last week we observed some
coredumps in dovecot's lmtp processes. For some emails, postfix mailq
reported:
> lost connection with nji9.de[/var/spool/postfix/private/dovecot-lmtp] while
sending end of data -- message may be sent more than once
Indeed, some users received some emails multiple times.
dovecot.log contained a lot of related lines, all of them looking like this:
> Sep 14 22:20:32 lmtp(user at example.com)<16323><abcdef:24>:
Info: sieve: Execution of script /home/vmail/example.com/user/.dovecot.sieve
failed, but implicit keep was successful (user logfile
/home/vmail/example.com/user/.dovecot.sieve.log may reveal additional details)
> Sep 14 22:20:32 lmtp(16323): Panic: file mail-user.c: line 229
(mail_user_deinit): assertion failed: ((*user)->refcount == 1)
> Sep 14 22:20:32 lmtp(16323): Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(backtrace_append+0x43) [0x68ac383e6073] ->
/usr/lib/dovecot/libdovecot.so.0(backtrace_get+0x20) [0x68ac383e6190] ->
/usr/lib/dovecot/libdovecot.so.0(+0xfaf1f) [0x68ac383f2f1f] ->
/usr/lib/dovecot/libdovecot.so.0(+0xfafb1) [0x68ac383f2fb1] ->
/usr/lib/dovecot/libdovecot.so.0(+0x4cd20) [0x68ac38344d20] ->
/usr/lib/dovecot/libdovecot-storage.so.0(+0x38bbc) [0x68ac384f6bbc] ->
dovecot/lmtp(lmtp_local_data+0x400) [0xfb684d63190] ->
dovecot/lmtp(client_default_cmd_data+0x19d) [0xfb684d61c5d] ->
dovecot/lmtp(cmd_data_continue+0x191) [0xfb684d619e1] ->
/usr/lib/dovecot/libdovecot.so.0(+0x6cb09) [0x68ac38364b09] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x6b) [0x68ac38408ebb] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13b)
[0x68ac3840a5cb] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x51) [0x68ac38408f61]
-> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x41) [0x68ac38409131] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x14) [0x68ac3837af74] ->
dovecot/lmtp(main+0x235) [0xfb684d60615] ->
/usr/lib/libc.so.6(__libc_start_main+0xd5) [0x68ac3814ab25] ->
dovecot/lmtp(_start+0x2e) [0xfb684d6072e]
> Sep 14 22:20:33 lmtp(16323): Fatal: master: service(lmtp): child 16323
killed with signal 6 (core dumped)
Equally frequent, journalctl said:
> Sep 14 22:20:33 nji9.de systemd-coredump[16358]: Process 16323 (lmtp) of
user 0 dumped core.
> Found module linux-vdso.so.1 with build-id:
7b6fd2add8450c7af3684522368e4ce83f762f41
> Found module libgcc_s.so.1 with build-id:
7f8508bb914546ada778809b64b99d234337d835
> Found module libffi.so.7 with build-id:
de60e99f39569d11d09160bbdcd486cedc87d2b6
> Found module libp11-kit.so.0 with build-id:
5314ec746546ada6f442b6fdfae15eab9f6d3cdc
> Found module libcrypt.so.2 with build-id:
3743451bdaf36f951f926927633fd964813025d0
> Found module librt.so.1 with build-id:
75484da2d6f1515189eefa076e0a40328834cd16
> Found module libnss_systemd.so.2 with build-id:
22990ff716d182c427e26b7a3cf94048b55b3e75
> Found module libnss_files.so.2 with build-id:
1a36dfc01d3a1010b2ee79766a24a8090a3266d5
> Found module libdovecot-sieve.so.0 with build-id:
8f87ae1b5f982453421532a7ac0f309813add7ce
> Found module lib90_sieve_plugin.so with build-id:
4cd814cc28d0259b7f837b3b8583adabbf608d6a
> Found module lib10_quota_plugin.so with build-id:
a63664ff7754f0c234344a89f2d28aa3f6650929
> Found module libpthread.so.0 with build-id:
07c8f95b4f3251d08550217ad8a1f31066229996
> Found module libcrypto.so.1.1 with build-id:
6d23f0a3f354825868d044684fad31d482cc9210
> Found module libssl.so.1.1 with build-id:
959cd8f1dd43fc31aeb93caac4eda87c907ef18b
> Found module libssl_iostream_openssl.so with build-id:
7cde2343f52a797e4fe77de7d0e7c1cb4983706b
> Found module ld-linux-x86-64.so.2 with build-id:
040cc3dd10461562f177df39e3be2f3704258c3c
> Found module libdl.so.2 with build-id:
5abc547e7b0949f89f3c0e21ab0c8331a7440a8a
> Found module libc.so.6 with build-id:
4b406737057708c0e4c642345a703c47a61c73dc
> Found module libdovecot.so.0 with build-id:
e2c3dc8d5ee8012c83dc2a5f220de42e020857dc
> Found module libdovecot-storage.so.0 with build-id:
1c80627fdc89752d8dc749ecfefae1e31445bb67
> Found module libdovecot-lda.so.0 with build-id:
826670da875938b71bd20af87dab4eb2cbbfef61
> Found module lmtp with build-id: 1f51ab7200356943590ecee21d298c808833d4e2
> Stack trace of thread 16323:
> #0 0x000068ac3815fd22 raise (libc.so.6 + 0x3cd22)
> #1 0x000068ac38149862 abort (libc.so.6 + 0x26862)
> #2 0x000068ac38345084 n/a (libdovecot.so.0 + 0x4d084)
> #3 0x000068ac383f2fb1 n/a (libdovecot.so.0 + 0xfafb1)
> #4 0x000068ac38344d20 i_panic (libdovecot.so.0 + 0x4cd20)
> #5 0x000068ac384f6bbc n/a (libdovecot-storage.so.0 + 0x38bbc)
> #6 0x00000fb684d63190 lmtp_local_data (lmtp + 0x9190)
> #7 0x00000fb684d61c5d client_default_cmd_data (lmtp + 0x7c5d)
> #8 0x00000fb684d619e1 cmd_data_continue (lmtp + 0x79e1)
> #9 0x000068ac38364b09 n/a (libdovecot.so.0 + 0x6cb09)
> #10 0x000068ac38408ebb io_loop_call_io (libdovecot.so.0 + 0x110ebb)
> #11 0x000068ac3840a5cb io_loop_handler_run_internal (libdovecot.so.0 +
0x1125cb)
> #12 0x000068ac38408f61 io_loop_handler_run (libdovecot.so.0 + 0x110f61)
> #13 0x000068ac38409131 io_loop_run (libdovecot.so.0 + 0x111131)
> #14 0x000068ac3837af74 master_service_run (libdovecot.so.0 + 0x82f74)
> #15 0x00000fb684d60615 main (lmtp + 0x6615)
> #16 0x000068ac3814ab25 __libc_start_main (libc.so.6 + 0x27b25)
> #17 0x00000fb684d6072e _start (lmtp + 0x672e)
> Sep 14 22:20:33 nji9.de systemd[1]: systemd-coredump at 32-16357-0.service:
Deactivated successfully.
The sieve logfile, which was mentioned in dovecot.log, contains:
> sieve: info: started log at 2021-09-14 22:20:32 +0200.
> error: msgid=<abcdefghi at example.com>: fileinto action: failed to
store into mailbox 'INBOX.MyFolder': Mailbox doesn't exist:
INBOX.MyFolder.
After removing all failed sieve rules which appeared in the logs, the
mail queue was processed without errors. There were no core dumps any more.
The strange thing is that there are some failing sieve rules left. The
sieve log of one user still contains errors. But there are no coredumps
any more.
> sieve: info: started log at 2021-09-14 23:30:31 +0200.
> error: msgid=<abcdefghi at example.com>: fileinto action: failed to
store into mailbox 'INBOX.OtherFolder': Mailbox doesn't exist:
INBOX.OtherFolder.
Dovecot version: 2.3.16
Operating system or Linux distribution name: Arch Linux
CPU architecture: x86_64
Filesystem: ext4
Kernel: Linux nji9.de 5.13.16-hardened1-1-hardened #1 SMP PREEMPT Sun,
12 Sep 2021 20:28:26 +0000 x86_64 GNU/Linux
I found a possibly related change (same error message as in the logs) in
the dovecot changelog:
> 2021-08-18 19:49:43 +0200 Timo Sirainen <timo.sirainen at
open-xchange.com> (b401e41)
>
> imap: Fix mailbox leak if MOVE can't open the source mailbox
>
> Broken by 143b7c2b412ed8f155e812603fda81886bec466e
>
> Fixes: Panic: file mail-user.c: line 229 (mail_user_deinit): assertion
> failed: ((*user)->refcount == 1)
>
> M src/imap/cmd-copy.c
I don't know if that change fixes the issue. Note that there is no new
dovecot release yet.
Trying to reproduce the error would be hard because this is a production
system. We have coredumps, but as they might contain sensitive
information, we'd prefer to not send them over a public mailing list.
Do you have any clue on this issue?
Best regards,
the nji9.de crew
-------------- next part --------------
# dovecot -n
# 2.3.16 (7e2e900c1a): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.16 (09c29328)
# OS: Linux 5.13.16-hardened1-1-hardened x86_64 Arch Linux
# Hostname: nji9.de
auth_mechanisms = plain login
imap_capability = +SPECIAL-USE
log_path = /var/log/dovecot.log
mail_gid = vmail
mail_home = /home/vmail/%d/%n
mail_location = maildir:~/Maildir
mail_plugins = " quota"
mail_uid = vmail
mail_vsize_bg_after_count = 100
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character
vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy
include variables body enotify environment mailbox date index ihave duplicate
mime foreverypart extracttext
namespace inbox {
inbox = yes
location mailbox Drafts {
auto = subscribe
special_use = \Drafts
}
mailbox Sent {
auto = subscribe
special_use = \Sent
}
mailbox Spam {
auto = subscribe
special_use = \Junk
}
mailbox Trash {
auto = subscribe
special_use = \Trash
}
prefix }
passdb {
args = /etc/dovecot/dovecot-sqlite.conf
driver = sql
}
plugin {
quota = count
quota_grace = 10%%
quota_ignore_save_errors = yes
quota_max_mail_size = 30M
quota_rule2 = Trash:bytes=+100M
quota_status_nouser = DUNNO
quota_status_overquota = 552 5.2.2 Mailbox is full
quota_status_success = DUNNO
quota_vsizes = yes
sieve_after = /etc/dovecot/sieve-after
}
protocols = imap lmtp sieve
service auth {
unix_listener /var/spool/postfix/private/dovecot-sasl {
group = postfix
mode = 0660
user = postfix
}
}
service imap-login {
inet_listener imap {
address = 127.0.0.1
port = 50143
}
inet_listener imaps {
port = 50993
ssl = yes
}
}
service lmtp {
unix_listener /var/spool/postfix/private/dovecot-lmtp {
group = postfix
mode = 0660
user = postfix
}
vsz_limit = 4 G
}
service managesieve-login {
inet_listener sieve {
address = 127.0.0.1
port = 4190
}
}
service quota-status {
client_limit = 1
executable = quota-status -p postfix
inet_listener {
address = 127.0.0.1
port = 12340
}
vsz_limit = 1 G
}
ssl = required
ssl_cert = # removed
ssl_cipher_list = EECDH+AESGCM:EDH+AESGCM
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
ssl_prefer_server_ciphers = yes
userdb {
driver = prefetch
}
userdb {
args = /etc/dovecot/dovecot-sqlite.conf
driver = sql
}
protocol imap {
imap_idle_notify_interval = 29 mins
mail_max_userip_connections = 20
mail_plugins = " quota imap_quota"
}
protocol lmtp {
mail_plugins = " quota sieve"
}