mail-storage.c:2473 assertion failed: (!ctx->unfinished) (related to antispam?)

Wed Sep 27 15:44:30 EEST 2017

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 at 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 at 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 at entry=0x7fc5ef52e880 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:275
>> #5  0x00007fc5ef47f998 in mailbox_copy_int (_ctx=_ctx at entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2473
>> #6  0x00007fc5ef47f9ff in mailbox_copy (_ctx=_ctx at 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 at entry=0x55bae816d5e8) at imap-commands.c:200
>> #10 0x000055bae72ae322 in client_command_input (cmd=<optimized out>, cmd at 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 at entry=0x55bae8153990) at ioloop-epoll.c:223
>> #17 0x00007fc5ef1bb7d6 in io_loop_handler_run (ioloop=ioloop at 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 at 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 at 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 at entry=0x7ffc553b3ab0, mail=<optimized out>) at mail-storage.c:2473
>> 2473            i_assert(!ctx->unfinished);
>> (gdb)
>> #4  0x00007fc5ef136cf8 in i_panic (format=format at 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 = 
>> }
>
>