dovecot - Mar 2023 - dovecot crash with Panic: file istream-header-filter.c: line 663

Hi -

I'm hitting a crash in dovecot, I get this logged followed by a terse stack
trace and
systemd-coredump details not included here - full gdb stack trace and more
details are
further down:


Mar 12 10:32:26 goffin dovecot[8269]: imap-login: Login: user=<patman>,
method=PLAIN, rip=192.168.1.4, lip=192.168.1.1, mpid=8477, TLS,
session=<5RvGYLf2RrDAqAEE>
Mar 12 10:32:26 goffin audit[8304]: USER_AUTH pid=8304 uid=0 auid=4294967295
ses=4294967295 subj=kernel msg='op=PAM:authentication
grantors=pam_usertype,pam_localuser,pam_unix acct="patman"
exe="/usr/libexec/dovecot/auth" hostname=192.168.1.4 addr=192.168.1.4
terminal=dovecot res=success'
Mar 12 10:32:26 goffin audit[8304]: USER_ACCT pid=8304 uid=0 auid=4294967295
ses=4294967295 subj=kernel msg='op=PAM:accounting
grantors=pam_unix,pam_localuser acct="patman"
exe="/usr/libexec/dovecot/auth" hostname=192.168.1.4 addr=192.168.1.4
terminal=dovecot res=success'
Mar 12 10:32:26 goffin dovecot[8269]: imap-login: Login: user=<patman>,
method=PLAIN, rip=192.168.1.4, lip=192.168.1.1, mpid=8479, TLS,
session=<PnHKYLf2SrDAqAEE>
Mar 12 10:32:27 goffin dovecot[8269]:
imap(patman)<8452><r+ynYLf2PrDAqAEE>: Panic: file
istream-header-filter.c: line 663 (i_stream_header_filter_snapshot_free):
assertion failed: (snapshot->mstream->snapshot_pending)
Mar 12 10:32:27 goffin audit[8452]: ANOM_ABEND auid=4294967295 uid=1000 gid=1000
ses=4294967295 subj=kernel pid=8452 comm="imap"
exe="/usr/libexec/dovecot/imap" sig=6 res=1


email client is fairemail version 1.2042a on android, but an older version had
the same
problem.

I mainly use fairemail to read emails on my phone, and that is working fine but
I noticed
that deleted emails were not actually getting deleted, that it has a bunch of
"pending
operations" it has were not running, and that dovecot has been crashing
like this since
about feb 2 (over a month ago). I can't figure out what changed at that
time, but my cert
says it should have expired over a year ago, but the cert as created 26 months
ago.

log files only go back to Feb 5 so just missed that.

I generated a new cert but it's still crashing (I probably still need to do
something on
the client side or my setup is broken).

I assume there is something wrong or some "snapshot" thing that's
stuck, but since it's
crashing I can't figure out what the undelysing problem is.

Thanks for any help.

More details:

--------------------------------------------------------------------------------
# dovecot --version
2.3.20 (80a5ac675d)

Running with up to date fedora core 37.

--------------------------------------------------------------------------------

# dovecot -n
# 2.3.20 (80a5ac675d): /etc/dovecot/dovecot.conf
# OS: Linux 6.1.15-200.fc37.x86_64 x86_64 Fedora release 37 (Thirty Seven)
# Hostname: specu
mail_location = mbox:~/Mail:INBOX=~/Mail/inbox
mbox_write_locks = fcntl
namespace inbox {
  inbox = yes
  location   mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix }
passdb {
  driver = pam
}
ssl = required
ssl_cert = </etc/pki/dovecot/certs/dovecot.pem
ssl_cipher_list = PROFILE=SYSTEM
ssl_key = # hidden, use -P to show it
userdb {
  driver = passwd
}

--------------------------------------------------------------------------------

gdb backtrace via coredumpctl  debug PID:

Core was generated by `dovecot/imap'.
Program terminated with signal SIGABRT, Aborted.
--Type <RET> for more, q to quit, c to continue without paging-- 
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo
at entry=6, no_tid=no_tid at entry=0) at pthread_kill.c:44
44            return INTERNAL_SYSCALL_ERROR_P (ret) ? INTERNAL_SYSCALL_ERRNO
(ret) : 0;
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo
at entry=6, no_tid=no_tid at entry=0) at pthread_kill.c:44
#1  0x00007fa3840afec3 in __pthread_kill_internal (signo=6,
threadid=<optimized out>) at pthread_kill.c:78
#2  0x00007fa38405fa76 in __GI_raise (sig=sig at entry=6) at
../sysdeps/posix/raise.c:26
#3  0x00007fa3840497fc in __GI_abort () at abort.c:79
#4  0x00007fa3847541e3 in default_fatal_finish (status=0, type=LOG_TYPE_PANIC)
at ../lib/failures.c:465
#5  fatal_handler_real (ctx=<optimized out>, format=<optimized out>,
args=<optimized out>) at ../lib/failures.c:477
#6  0x00007fa3847ff5f7 in i_internal_fatal_handler (ctx=<optimized out>,
format=<optimized out>, args=<optimized out>) at
../lib/failures.c:879
#7  0x00007fa3847540e1 in i_panic (format=0x7fa384844040 "file %s: line %d
(%s): assertion failed: (%s)") at ../lib/failures.c:530
#8  0x00007fa38474fdf8 in i_stream_header_filter_snapshot_free
(_snapshot=<optimized out>) at ../lib-mail/istream-header-filter.c:663
#9  i_stream_header_filter_snapshot_free (_snapshot=0x56150ea92250) at
../lib-mail/istream-header-filter.c:655
#10 0x00007fa38480cb6c in i_stream_snapshot_free (_snapshot=_snapshot at
entry=0x56150ea9d2a0) at ../lib/istream.c:253
#11 0x00007fa38480cc14 in i_stream_unref (stream=0x56150ea9d338) at
../lib/istream.c:66
#12 0x00007fa3847dd179 in message_parse_header_deinit (_ctx=_ctx at
entry=0x56150ea9d0c8) at ../lib-mail/message-header-parser.c:52
#13 0x00007fa3847deea1 in preparsed_parse_next_header (ctx=0x56150ea9d050,
block_r=0x7ffc8222ca70) at ../lib-mail/message-parser-from-parts.c:310
#14 0x00007fa3847dfedc in message_parser_parse_next_block (ctx=ctx at
entry=0x56150ea9d050, block_r=block_r at entry=0x7ffc8222ca70) at
../lib-mail/message-parser.c:838
#15 0x00007fa3847e0029 in message_parser_parse_header (ctx=0x56150ea9d050,
hdr_size=hdr_size at entry=0x56150ea5ff00,
    callback=callback at entry=0x7fa3849aa3f0
<index_mail_parse_part_header_cb>, context=context at
entry=0x56150ea5fc78) at ../lib-mail/message-parser.c:877
#16 0x00007fa3849aa60a in index_mail_parse_headers_internal (mail=mail at
entry=0x56150ea5fc78, headers=headers at entry=0x0) at
index/index-mail-headers.c:465
#17 0x00007fa3849aa71e in index_mail_parse_headers (mail=0x56150ea5fc78,
headers=0x0, reason=<optimized out>) at index/index-mail-headers.c:499
#18 0x00007fa3849b021e in index_mail_parse_bodystructure_full
(mail=0x56150ea5fc78, field=MAIL_CACHE_IMAP_BODYSTRUCTURE) at
index/index-mail.c:1491
#19 0x00007fa3849b02b3 in index_mail_parse_bodystructure (mail=mail at
entry=0x56150ea5fc78, field=field at entry=MAIL_CACHE_IMAP_BODYSTRUCTURE) at
index/index-mail.c:1515
#20 0x00007fa3849b06cd in index_mail_get_special (_mail=0x56150ea5fc78,
field=<optimized out>, value_r=0x7ffc8222cbe0) at index/index-mail.c:1713
#21 0x00007fa38492fa1e in mail_get_special (mail=<optimized out>,
field=field at entry=MAIL_FETCH_IMAP_BODYSTRUCTURE, value_r=value_r at
entry=0x7ffc8222cbe0)
    at /usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/lib-storage/mail.c:418
#22 0x000056150dcf458c in fetch_bodystructure (ctx=0x56150ea57530,
mail=<optimized out>, context=<optimized out>)
    at /usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-fetch.c:740
#23 0x000056150dcfa3f3 in imap_fetch_more_int (ctx=ctx at entry=0x56150ea57530,
cancel=false) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-fetch.c:562
#24 0x000056150dcfa6cd in imap_fetch_more (ctx=0x56150ea57530,
cmd=0x56150ea57368) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-fetch.c:617
#25 0x000056150dceed11 in cmd_fetch (cmd=0x56150ea57368) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/cmd-fetch.c:382
#26 0x000056150dcf79a5 in command_exec (cmd=cmd at entry=0x56150ea57368) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-commands.c:201
#27 0x000056150dcfd712 in client_command_input (cmd=<optimized out>, cmd
at entry=0x56150ea57368)
    at /usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-client.c:1232
#28 0x000056150dcfd7b8 in client_command_input (cmd=<optimized out>) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-client.c:1302
#29 0x000056150dcfdc05 in client_handle_next_command (remove_io_r=<synthetic
pointer>, client=0x56150ea567f8)
    at /usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-client.c:1344
#30 client_handle_input (client=client at entry=0x56150ea567f8) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-client.c:1358
#31 0x000056150dcfdfd4 in client_input (client=0x56150ea567f8) at
/usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/imap-client.c:1402
#32 0x00007fa3848183ad in io_loop_call_io (io=0x56150ea890b0) at
../lib/ioloop.c:737
#33 0x00007fa38481973a in io_loop_handler_run_internal (ioloop=ioloop at
entry=0x56150ea2def0) at ../lib/ioloop-epoll.c:222
#34 0x00007fa3848197e4 in io_loop_handler_run (ioloop=ioloop at
entry=0x56150ea2def0) at ../lib/ioloop.c:789
#35 0x00007fa3848199a0 in io_loop_run (ioloop=0x56150ea2def0) at
../lib/ioloop.c:762
#36 0x00007fa384788bf7 in master_service_run (service=0x56150ea2dd40,
callback=callback at entry=0x56150dd00ae0 <client_connected>) at
../lib-master/master-service.c:869
#37 0x000056150dce9c4d in main (argc=<optimized out>, argv=<optimized
out>) at /usr/src/debug/dovecot-2.3.20-1.fc37.x86_64/src/imap/main.c:566
(gdb)

On Sun, Mar 12, 2023 at 11:17:43AM -0700, Patrick Mansfield
wrote:
> 
> email client is fairemail version 1.2042a on android, but an older version
had the same
> problem.
> 
> I mainly use fairemail to read emails on my phone, and that is working fine
but I noticed
> that deleted emails were not actually getting deleted, that it has a bunch
of "pending
> operations" it has were not running, and that dovecot has been
crashing like this since
> about feb 2 (over a month ago). I can't figure out what changed at that
time, but my cert
> says it should have expired over a year ago, but the cert as created 26
months ago.
> 
> log files only go back to Feb 5 so just missed that.
> 
> I generated a new cert but it's still crashing (I probably still need
to do something on
> the client side or my setup is broken).
> 
> I assume there is something wrong or some "snapshot" thing
that's stuck, but since it's
> crashing I can't figure out what the undelysing problem is.
Another thing I noticed:

I think I deleted all emails left in the "Trash" folder outside of
imap on Feb 4 (using
mutt locally) - or that that folder was modified on Feb 4, that is also the same
timestamp
as my ~/Mail/.imap directory, and is about the time I think it started crashing.

And that these were all dated Feb 4:

$ ls -ld ~/Mail/.imap ~/Mail/Trash ~/Mail/.imap/dovecot.list.index
drwx------. 118 patman patman    4096 Feb  4 09:29 /home/patman/Mail/.imap
-rw-------    1 patman patman   14696 Feb  4 09:11
/home/patman/Mail/.imap/dovecot.list.index
-rw-------    1 patman patman 1459841 Feb  4 09:11 /home/patman/Mail/Trash

-- Patrick

On 12. Mar 2023, at 20.17, Patrick Mansfield <patmans at yahoo.com>
wrote:
> 
> Mar 12 10:32:27 goffin dovecot[8269]:
imap(patman)<8452><r+ynYLf2PrDAqAEE>: Panic: file
istream-header-filter.c: line 663 (i_stream_header_filter_snapshot_free):
assertion failed: (snapshot->mstream->snapshot_pending)
This is unfortunately rather difficult to debug. First you should find out which
folder and mail this is happening in. You can do that with gdb:
> #16 0x00007fa3849aa60a in index_mail_parse_headers_internal (mail=mail at
entry=0x56150ea5fc78, headers=headers at entry=0x0) at
index/index-mail-headers.c:465
fr 16
p mail.box.vname
p mail.uid

Likely deleting that mail manually from the mbox will fix it. Of course, it
would be nice if we were able to reproduce the bug also. Once you've found
the broken folder, could you anonymize the mbox file contents and send it to me
privately? https://github.com/dovecot/tools/blob/main/mbox-anonymize.pl can help
you do it. Although I'm not sure if even that is enough to reproduce the bug
- might need the dovecot.index* files also but those contain cached headers from
the emails, which can be rather sensitive data.

Other things besides deleting the mail that might help, and would be useful to
know whether they help:

 * doveadm fetch -u user imap.bodystructure mailbox $folder uid $uid
 * doveadm mailbox cache remove -u user mailbox $folder uid $uid

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20230313/1063af43/attachment.htm>