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@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@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@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@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@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