Op 9/27/2017 om 2:36 PM schreef Matthijs Kooijman:

Hey folks,

apologies for the useless subject on my original mail, forgot to update it.

Two more bits of info. Here's the log output related to this crash:

dovecot: imap-login: Login: user=<2014>, method=PLAIN, rip=217.122.126.195, lip=10.42.0.13, mpid=10569, TLS, session=<IsP37ypaFYHZen7D> dovecot: imap(2014): Panic: file mail-storage.c: line 2473 (mailbox_copy_int): assertion failed: (!ctx->unfinished) (I've omitted the raw backtrace)

And, I just discovered that (it seems that) whenever such a crash happens, an empty /tmp/antispam-mail-xyz directory is created, which makes me suspect that at least the antispam plugin is involved in these imap sessions, and might the the one causing the crash. I'm running the latest antispam version from Debian (2.0+20170109-1+b2, which also seems to be the latest upstream).

That sounds plausible. However, since you're using a very recent Dovecot now, you should consider using IMAPSieve instead:

https://wiki2.dovecot.org/HowTo/AntispamWithSieve

Regards,

Stephan.

Gr.

Matthijs

On Wed, Sep 27, 2017 at 02:21:09PM +0200, Matthijs Kooijman wrote:

...

(I'm not subscribed, please keep me CC'd)

Hi,

since a few months I'm experiencing repeated dovecot crashes. I mostly see them in the logs, I haven't had any users complain, so I haven't looked closely until now. I was originally using an older version fro mDebian and hoped that a newer future version would already fix this, but I just upgraded to version 1:2.2.32-2 from Debian testing, and the problem persists.

This crash sometimes happens occasionally, but often happens repeatedly for some time (presumably a client keeps retrying) but can also be gone for hours or days (presumably the client no longer connects). I haven't been able to definitively figure out what client causes this, but based on the user ID I suspect it is Mail.app on OSX.

I managed to get a core dump, which gave me the stacktrace below. I've also attached my config file. If any other details are relevant, just ask and I can squeeze them out of the core dump (but I'd rather not publicly share the file). I can probably set up rawlog to capture the actual IMAP session if needed, though I have no time for that right now.

Gr.

Matthijs

51 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51 #1 0x00007fc5eed9c3fa in __GI_abort () at abort.c:89 #2 0x00007fc5ef1a609a in default_fatal_finish (type=LOG_TYPE_PANIC, status=status@entry=0) at failures.c:201 #3 0x00007fc5ef1a619a in i_internal_fatal_handler (ctx=0x7ffc553b38d0, format=<optimized out>, args=<optimized out>) at failures.c:670 #4 0x00007fc5ef136cf8 in i_panic (format=format@entry=0x7fc5ef52e880 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:275 #5 0x00007fc5ef47f998 in mailbox_copy_int (_ctx=_ctx@entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2473 #6 0x00007fc5ef47f9ff in mailbox_copy (_ctx=_ctx@entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2489 #7 0x000055bae72a2f5f in fetch_and_copy (copy_count_r=<synthetic pointer>, src_uidset_r=<synthetic pointer>, search_args=<optimized out>, src_trans_r=0x7ffc553b3a88, t=<optimized out>, move=<optimized out>, cmd=0x55bae816d5e8) at cmd-copy.c:72 #8 cmd_copy_full (cmd=0x55bae816d5e8, move=false) at cmd-copy.c:139 #9 0x000055bae72afd9c in command_exec (cmd=cmd@entry=0x55bae816d5e8) at imap-commands.c:200 #10 0x000055bae72ae322 in client_command_input (cmd=<optimized out>, cmd@entry=0x55bae816d5e8) at imap-client.c:1088 #11 0x000055bae72ae3bc in client_command_input (cmd=<optimized out>) at imap-client.c:1148 #12 0x000055bae72ae77d in client_handle_next_command (remove_io_r=<synthetic pointer>, client=0x55bae816bcf8) at imap-client.c:1190 #13 client_handle_input (client=0x55bae816bcf8) at imap-client.c:1202 #14 0x000055bae72aeccc in client_input (client=0x55bae816bcf8) at imap-client.c:1249 #15 0x00007fc5ef1bb742 in io_loop_call_io (io=0x55bae816d4e0) at ioloop.c:599 #16 0x00007fc5ef1bcd8e in io_loop_handler_run_internal (ioloop=ioloop@entry=0x55bae8153990) at ioloop-epoll.c:223 #17 0x00007fc5ef1bb7d6 in io_loop_handler_run (ioloop=ioloop@entry=0x55bae8153990) at ioloop.c:648 #18 0x00007fc5ef1bb988 in io_loop_run (ioloop=0x55bae8153990) at ioloop.c:623 #19 0x00007fc5ef141353 in master_service_run (service=0x55bae8153830, callback=<optimized out>) at master-service.c:666 #20 0x000055bae72a1139 in main (argc=<optimized out>, argv=<optimized out>) at main.c:491 (gdb) up 9 #9 0x000055bae72afd9c in command_exec (cmd=cmd@entry=0x55bae816d5e8) at imap-commands.c:200 200 finished = cmd->func(cmd); (gdb) p *cmd $14 = {prev = 0x0, next = 0x0, client = 0x55bae816bcf8, pool = 0x55bae816d5c0, tag = 0x55bae816d750 "7.119309", name = 0x55bae816d760 "UID COPY", args = 0x55bae816d770 "20004 INBOX", human_args = 0x55bae816d780 "20004 INBOX", cmd_flags = COMMAND_FLAG_BREAKS_SEQS, tagline_reply = 0x0, func = 0x55bae72a33e0 <cmd_copy>, context = 0x0, module_contexts = {arr = {buffer = 0x55bae816d6e8, element_size = 8}, v = 0x55bae816d6e8, v_modifiable = 0x55bae816d6e8}, parser = 0x55bae8157aa0, state = CLIENT_COMMAND_STATE_WAIT_INPUT, stats = {start_time = {tv_sec = 1506507612, tv_usec = 777163}, last_run_timeval = {tv_sec = 1506507612, tv_usec = 777163}, start_ioloop_wait_usecs = 46340, running_usecs = 0, lock_wait_usecs = 0, bytes_in = 0, bytes_out = 0}, stats_start = {timeval = { tv_sec = 1506507612, tv_usec = 777241}, lock_wait_usecs = 0, bytes_in = 91, bytes_out = 852}, sync = 0x0, uid = 1, cancel = 0, param_error = 0, search_save_result = 0, search_save_result_used = 0, temp_executed = 0, tagline_sent = 0, executing = 1} (gdb) down #8 cmd_copy_full (cmd=0x55bae816d5e8, move=false) at cmd-copy.c:139 139 ret = fetch_and_copy(cmd, move, t, &src_trans, search_args, (gdb) #7 0x000055bae72a2f5f in fetch_and_copy (copy_count_r=<synthetic pointer>, src_uidset_r=<synthetic pointer>, search_args=<optimized out>, src_trans_r=0x7ffc553b3a88, t=<optimized out>, move=<optimized out>, cmd=0x55bae816d5e8) at cmd-copy.c:72 72 if (mailbox_copy(&save_ctx, mail) < 0) (gdb) #6 0x00007fc5ef47f9ff in mailbox_copy (_ctx=_ctx@entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2489 2489 return mailbox_copy_int(_ctx, mail); (gdb) #5 0x00007fc5ef47f998 in mailbox_copy_int (_ctx=_ctx@entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2473 2473 i_assert(!ctx->unfinished); (gdb) #4 0x00007fc5ef136cf8 in i_panic (format=format@entry=0x7fc5ef52e880 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:275 275 fatal_handler(&ctx, format, args);

# 2.2.32 (dfbe293d4): /etc/dovecot/dovecot.conf # Pigeonhole version 0.4.20 (7cd71ba) # OS: Linux 4.4.0-1-amd64 x86_64 Debian 9.1 auth_mechanisms = plain login log_timestamp = "%Y-%m-%d %H:%M:%S " mail_access_groups = spamd-access mail_gid = virtual-mail mail_location = Maildir:~/Folders:INBOX=~/INBOX:LAYOUT=fs mail_uid = virtual-mail 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 passdb { args = /etc/dovecot/dovecot-ldap.conf driver = ldap } plugin { antispam_backend = pipe antispam_pipe_program = /usr/local/bin/trainspam antispam_pipe_program_notspam_arg = ham antispam_pipe_program_spam_arg = spam antispam_spam = Spam;ProbablySpam;Ongewenste e-mail;Junk antispam_trash_pattern_ignorecase = trash;Deleted *;Prullenbak;Verwijderde * antispam_unsure = INBOX sieve = ~/sieve sieve_dir = ~/sieve.d sieve_global_path = /etc/dovecot/sieve/default } protocols = imap sieve service auth { unix_listener auth-client { group = Debian-exim mode = 0600 user = Debian-exim } unix_listener auth-master { group = virtual-mail mode = 0600 user = virtual-mail } user = nobody } ssl_cert = </etc/letsencrypt/live/tikatika.nl/fullchain.pem ssl_key = # hidden, use -P to show it userdb { args = home=/data/mail/%u allow_all_users=yes uid=virtual-mail gid=virtual-mail driver = static } protocol imap { mail_plugins = antispam } protocol lda { lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes mail_plugins = sieve postmaster_address = }

Hi Aki,

To verify whether it's caused by antispam plugin, you could copy/move mail to Spam folder and see if it crashes? That's inconclusive: I can copy stuff in and out of my Spam folder just fine using mutt. I've never seen the crash for my user so far, which suggests this is specific to one IMAP client (or otherwise dependent on circumstances).

I'll ask the user who did have the crash to move some mail, to see if that triggers it again.

Yesterday, the crash would happen repeatedly in long bursts, on connections from the same user, which were probably retries on a failing mail copy. I disabled the antispam plugin for a while, which showed some non-crashing connections from this same user (presumably completing the copy). After re-enabling anti-spam, I've not seen the crash again for this user, probably because there were no pending problematic copies anymore.

Gr.

Matthijs