lmtp process dumps core after sieve error

Wed Sep 15 18:32:29 EEST 2021

> On 15/09/2021 17:12 admin <admin at nji9.de> wrote:
> 
>  
> 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) [0
 x68ac38409131] -> /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

Hi!

This is most likely fixed with 

https://github.com/dovecot/pigeonhole/compare/9f3002393fe1c1fe317121d03591569dac120739%5E..4596d39908a868783fae9a0c2fd264409c0aaa96.patch

Aki