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

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 = 
>> }
>
>

On 27.09.2017 15:44, Stephan Bosch wrote:
> 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
>>>
To verify whether it's caused by antispam plugin, you could copy/move
mail to Spam folder and see if it crashes?

Aki

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20170928/17bf51d9/attachment.sig>

Hi folks,

I did a bit more digging in the coredump and found that the crash
happens when copying a file into any folder that is configured as
"unusre" using the "antispam_unsure" config variable. This
was
originally my INBOX, but I just configured some random folder as
"unsure" as well, and the same crash happens reproducibly (now also
with
mutt, not just Mail.app).

I understand that antispam isn't the recommended way of approaching this
anymore, but perhaps someone still wants to fix this?

Gr.

Matthijs
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20170928/c1f7e479/attachment.sig>