Re: 2.13 read, i_stream_read_memarea: assertion failed: (!stream->blocking)

On 2021-01-24, Stuart Henderson stu@spacehopper.org wrote:

I'm seeing this on some mailboxes with 2.13 on OpenBSD amd64 (recent snapshot):

dovecot: imap(sthen)<47220><ARy1oKS5lWDDX7sa>: Panic: file istream.c: line 332 (i_stream_read_memarea): assertion failed: (!stream->blocking)

Using sieve, imapsieve, replicator, zlib (zlib_save = lz4 and has been for some time, so the relevant messages probably use this). Using mmap_disable because OpenBSD.

Any suggestions how to handle it, preferably automatically? (even if a message is corrupt/lost it would be really nice if a standard client could still access the mailbox rather than kill the imap process while reading headers).

Thought I'd try doveadm force-resync ("For sdbox and mdbox mailboxes the storage files will be also checked") but this doesn't help.

Getting some ideas for the seemingly related thread about zstd/xz https://dovecot.org/pipermail/dovecot/2020-September/119890.html I've had a play with doveadm fetch.

Doing 'doveadm fetch -u sthen "uid text" mailbox ports | grep ^uid | tail' I find various messages from around June/July 2020 that trigger the crash. Expunging the last displayed uid at that point I get further but I run into more after a few messages. I don't mind doing that with this mailbox to get things working but if it can be used to provide/test something more robust that would be better.

Using "doveadm -o mail_plugins=virtual fetch" I see that they're definitely lz4 compressed.

Seems odd but if I do text fetches by uid I don't run into any failure?

$ for i in cat /tmp/uid.p|cut -d: -f2;do doveadm fetch -u sthen text mailbox ports uid $i > /dev/null || echo $i;done [no output]

Any ideas?

bt first for ease of reading, followed by bt full in case it has any additional clues.

(gdb) bt #0 thrkill () at /tmp/-:3 #1 0x00000e9158c7c3ae in _libc_abort () at /usr/src/lib/libc/stdlib/abort.c:51 #2 0x00000e91adc00c26 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at failures.c:459 #3 0x00000e91adbff034 in fatal_handler_real (ctx=0x7f7ffffcdd90, format=<optimized out>, args=<optimized out>) at failures.c:471 #4 0x00000e91adbfffb1 in i_internal_fatal_handler (ctx=0x0, format=0x6 , args=0x0) at failures.c:866 #5 0x00000e91adbff266 in i_panic (format=0x6 ) at failures.c:523 #6 0x00000e91adc0f15c in i_stream_read_memarea (stream=0xe917ead3480) at istream.c:332 #7 0x00000e91adc1925f in read_more (sstream=0xe91431c4800) at istream-seekable.c:149 #8 0x00000e91adc19090 in read_from_buffer (sstream=0xe91431c4800, ret_r=0x7f7ffffcded8) at istream-seekable.c:204 #9 0x00000e91adc1856d in i_stream_seekable_read (stream=0xe91431c4800) at istream-seekable.c:265 #10 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91431c4880) at istream.c:313 #11 0x00000e91adc16bbc in i_stream_limit_read (stream=0xe91e9ccca00) at istream-limit.c:49 #12 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9ccca80) at istream.c:313 #13 0x00000e91adc0f79c in i_stream_read_copy_from_parent (istream=<optimized out>) at istream.c:387 #14 0x00000e918e9729fa in i_stream_mail_read (stream=0xe91e9ccc000) at istream-mail.c:115 #15 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9ccc080) at istream.c:313 #16 0x00000e91adc104f5 in i_stream_read (stream=0xe91e9ccc080) at istream.c:271 #17 i_stream_read_data (stream=0xe91e9ccc080, data_r=0x7f7ffffce110, size_r=0x7f7ffffce100, threshold=1) at istream.c:747 #18 0x00000e91adbd6a18 in i_stream_read_bytes (stream=0x0, data_r=<optimized out>, size_r=<optimized out>, wanted=<optimized out>) at ../../src/lib/istream.h:214 #19 message_parse_header_next (ctx=0xe9183e1b180, hdr_r=0x7f7ffffce1d0) at message-header-parser.c:85 #20 0x00000e91adbceef2 in read_header (mstream=0xe91e9cc6000) at istream-header-filter.c:195 #21 i_stream_header_filter_read (stream=0xe91e9cc6000) at istream-header-filter.c:450 #22 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9cc6080) at istream.c:313 #23 0x00000e91adc104f5 in i_stream_read (stream=0xe91e9cc6080) at istream.c:271 #24 i_stream_read_data (stream=0xe91e9cc6080, data_r=0x7f7ffffce2c0, size_r=0x7f7ffffce2c8, threshold=0) at istream.c:747 #25 0x00000e91adbdc07b in i_stream_read_bytes (stream=0xe91e9cc6080, data_r=<optimized out>, size_r=<optimized out>, wanted=) at ../../src/lib/istream.h:214 #26 message_get_header_size (input=0xe91e9cc6080, hdr=0x7f7ffffce328, has_nuls_r=0x7f7ffffce3b7) at message-size.c:19 #27 0x00000e8f25e767d9 in imap_msgpart_get_partial_header (mail=0xe91e9cc4848, mail_input=<optimized out>, msgpart=0xe91c92a2048, virtual_size_r=<optimized out>, result_r=0x7f7ffffce408, have_crlfs_r=<optimized out>) at imap-msgpart.c:401 #28 imap_msgpart_open_normal (mail=<optimized out>, msgpart=0xe91c92a2048, part=<optimized out>, virtual_size_r=<optimized out>, result_r=0x7f7ffffce408, have_crlfs_r=<optimized out>) at imap-msgpart.c:637 #29 imap_msgpart_open (mail=<optimized out>, msgpart=0xe91c92a2048, result_r=0x7f7ffffce408) at imap-msgpart.c:706 #30 0x00000e8f25e672ff in fetch_body_msgpart (ctx=0xe9159845368, mail=<optimized out>, body=0xe91e9cb4398) at imap-fetch-body.c:184 #31 0x00000e8f25e65837 in imap_fetch_more_int (ctx=0xe9159845368, cancel=false) at imap-fetch.c:562 #32 0x00000e8f25e6552c in imap_fetch_more (ctx=0xe9159845368, cmd=0xe9159845048) at imap-fetch.c:617 #33 0x00000e8f25e55521 in cmd_fetch (cmd=0xe9159845048) at cmd-fetch.c:337 #34 0x00000e8f25e62d12 in command_exec (cmd=0xe9159845048) at imap-commands.c:201 #35 0x00000e8f25e61576 in client_command_input (cmd=0xe9159845048) at imap-client.c:1204 #36 0x00000e8f25e61682 in client_command_input (cmd=0xe9159845048) at imap-client.c:1269 #37 0x00000e8f25e5ffb4 in client_handle_next_command (client=0xe9159845848, remove_io_r=<optimized out>) at imap-client.c:1313 #38 client_handle_input (client=0xe9159845848) at imap-client.c:1327 #39 0x00000e8f25e5e755 in client_input (client=0xe9159845848) at imap-client.c:1371 #40 0x00000e91adc1c851 in io_loop_call_io (io=0xe91eb5d0b00) at ioloop.c:714 #41 0x00000e91adc1f84c in io_loop_handler_run_internal (ioloop=0xe9162373d00) at ioloop-kqueue.c:164 #42 0x00000e91adc1cfd9 in io_loop_handler_run (ioloop=0xe9162373d00) at ioloop.c:766 #43 0x00000e91adc1cce8 in io_loop_run (ioloop=0xe9162373d00) at ioloop.c:739 #44 0x00000e91adb77655 in master_service_run (service=0xe9193c39600, callback=0x6) at master-service.c:853 #45 0x00000e8f25e70dd1 in main (argc=1, argv=<optimized out>) at main.c:532

(gdb) bt full #0 thrkill () at /tmp/-:3 No locals. #1 0x00000e9158c7c3ae in _libc_abort () at /usr/src/lib/libc/stdlib/abort.c:51 sa = { __sigaction_u = { __sa_handler = 0x0, __sa_sigaction = 0x0 }, sa_mask = 4294967295, sa_flags = 0 } mask = 4294967263 #2 0x00000e91adc00c26 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at failures.c:459 recursed = 0 backtrace = <optimized out> #3 0x00000e91adbff034 in fatal_handler_real (ctx=0x7f7ffffcdd90, format=<optimized out>, args=<optimized out>) at failures.c:471 status = 6 #4 0x00000e91adbfffb1 in i_internal_fatal_handler (ctx=0x0, format=0x6 , args=0x0) at failures.c:866 No locals. #5 0x00000e91adbff266 in i_panic (format=0x6 ) at failures.c:523 ctx = { type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0, timestamp_usecs = 0, log_prefix = 0x0, log_prefix_type_pos = 0 } args = {{ gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7f7ffffcddf0, reg_save_area = 0x7f7ffffcdce0 }} #6 0x00000e91adc0f15c in i_stream_read_memarea (stream=0xe917ead3480) at istream.c:332 _stream = 0xe917ead3400 old_size = 0 ret = 0 #7 0x00000e91adc1925f in read_more (sstream=0xe91431c4800) at istream-seekable.c:149 ret = <optimized out> size = <optimized out> #8 0x00000e91adc19090 in read_from_buffer (sstream=0xe91431c4800, ret_r=0x7f7ffffcded8) at istream-seekable.c:204 old_skip = <optimized out> stream = 0xe91431c4800 size = <optimized out> data = <optimized out> avail_size = <optimized out> #9 0x00000e91adc1856d in i_stream_seekable_read (stream=0xe91431c4800) at istream-seekable.c:265 sstream = 0xe91431c4800 ret = 16019855444480 size = <optimized out> data = <optimized out> pos = <optimized out> #10 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91431c4880) at istream.c:313 _stream = 0xe91431c4800 old_size = 0 ret = <optimized out> #11 0x00000e91adc16bbc in i_stream_limit_read (stream=0xe91e9ccca00) at istream-limit.c:49 lstream = 0xe91e9ccca00 pos = 16017421909770 ret = <optimized out> left = <optimized out> #12 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9ccca80) at istream.c:313 _stream = 0xe91e9ccca00 old_size = 0 ret = <optimized out> #13 0x00000e91adc0f79c in i_stream_read_copy_from_parent (istream=<optimized out>) at istream.c:387 stream = 0xe91e9ccc000 pos = <optimized out> ret = <optimized out> #14 0x00000e918e9729fa in i_stream_mail_read (stream=0xe91e9ccc000) at istream-mail.c:115 mstream = 0xe91e9ccc000 ret = <optimized out> size = <optimized out> #15 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9ccc080) at istream.c:313 _stream = 0xe91e9ccc000 old_size = 0 ret = <optimized out> #16 0x00000e91adc104f5 in i_stream_read (stream=0xe91e9ccc080) at istream.c:271 _stream = 0xe91e9ccc000 ret = <optimized out> #17 i_stream_read_data (stream=0xe91e9ccc080, data_r=0x7f7ffffce110, size_r=0x7f7ffffce100, threshold=1) at istream.c:747 read_more = false ret = #18 0x00000e91adbd6a18 in i_stream_read_bytes (stream=0x0, data_r=<optimized out>, size_r=<optimized out>, wanted=<optimized out>) at ../../src/lib/istream.h:214 No locals. #19 message_parse_header_next (ctx=0xe9183e1b180, hdr_r=0x7f7ffffce1d0) at message-header-parser.c:85 skip = line = 0xe9183e1b180 colon_pos = 4294967295 no_newline = crlf_newline = continued = false size = 0 msg = 0xe91adafee50 "" startpos = 0 continues = i = <optimized out> parse_size = <optimized out> ret = <optimized out> last_crlf = <optimized out> last_no_newline = <optimized out> #20 0x00000e91adbceef2 in read_header (mstream=0xe91e9cc6000) at istream-header-filter.c:195 highwater_offset = <optimized out> max_buffer_size = 8192 hdr = 0x0 hdr_ret = <optimized out> ret = <optimized out> ret2 = <optimized out> #21 i_stream_header_filter_read (stream=0xe91e9cc6000) at istream-header-filter.c:450 mstream = 0xe91e9cc6000 v_offset = <optimized out> ret = <optimized out> #22 0x00000e91adc0f0a4 in i_stream_read_memarea (stream=0xe91e9cc6080) at istream.c:313 _stream = 0xe91e9cc6000 old_size = 0 ret = <optimized out> #23 0x00000e91adc104f5 in i_stream_read (stream=0xe91e9cc6080) at istream.c:271 _stream = 0xe91e9cc6000 ret = <optimized out> #24 i_stream_read_data (stream=0xe91e9cc6080, data_r=0x7f7ffffce2c0, size_r=0x7f7ffffce2c8, threshold=0) at istream.c:747 read_more = false ret = #25 0x00000e91adbdc07b in i_stream_read_bytes (stream=0xe91e9cc6080, data_r=<optimized out>, size_r=<optimized out>, wanted=) at ../../src/lib/istream.h:214 No locals. #26 message_get_header_size (input=0xe91e9cc6080, hdr=0x7f7ffffce328, has_nuls_r=0x7f7ffffce3b7) at message-size.c:19 size = 0 msg = 0xe91adafee50 "" startpos = missing_cr_count = ret = <optimized out> i = <optimized out> #27 0x00000e8f25e767d9 in imap_msgpart_get_partial_header (mail=0xe91e9cc4848, mail_input=<optimized out>, msgpart=0xe91c92a2048, virtual_size_r=<optimized out>, result_r=0x7f7ffffce408, have_crlfs_r=<optimized out>) at imap-msgpart.c:401 hdr_size = { physical_size = 0, virtual_size = 0, lines = 0 } hdr_fields = 0xe91c92a21f8 hdr_count = <optimized out> input = 0xe91e9cc6080 has_nuls = false #28 imap_msgpart_open_normal (mail=<optimized out>, msgpart=0xe91c92a2048, part=<optimized out>, virtual_size_r=<optimized out>, result_r=0x7f7ffffce408, have_crlfs_r=<optimized out>) at imap-msgpart.c:637 hdr_size = { physical_size = 0, virtual_size = 0, lines = 0 } body_size = { physical_size = 0, virtual_size = 0, lines = 0 } input = <optimized out> unknown_crlfs = part_size = #29 imap_msgpart_open (mail=<optimized out>, msgpart=0xe91c92a2048, result_r=0x7f7ffffce408) at imap-msgpart.c:706 part = <optimized out> ret = <optimized out> virtual_size = 1 binary = <optimized out> have_crlfs = <optimized out> #30 0x00000e8f25e672ff in fetch_body_msgpart (ctx=0xe9159845368, mail=<optimized out>, body=0xe91e9cb4398) at imap-fetch-body.c:184 result = { input = 0x0, size = 0, size_field = (unknown: 0), binary_decoded_input_has_nuls = false } str = <optimized out> #31 0x00000e8f25e65837 in imap_fetch_more_int (ctx=0xe9159845368, cancel=false) at imap-fetch.c:562 _data_stack_cur_id = <optimized out> client = <optimized out> ret = <optimized out> handlers = 0xe91e9cb4020 count = 5 #32 0x00000e8f25e6552c in imap_fetch_more (ctx=0xe9159845368, cmd=0xe9159845048) at imap-fetch.c:617 ret = <optimized out> #33 0x00000e8f25e55521 in cmd_fetch (cmd=0xe9159845048) at cmd-fetch.c:337 qresync_args = { qresync_sample_seqset = 0xe9159845368, qresync_sample_uidset = 0xe9159845020 } args = <optimized out> send_vanished = <optimized out> client = 0xe9159845848 messageset = <optimized out> search_args = 0x0 ret = <optimized out> ctx = 0x0 next_arg = <optimized out> list_arg = <optimized out> #34 0x00000e8f25e62d12 in command_exec (cmd=0xe9159845048) at imap-commands.c:201 hook = <optimized out> #35 0x00000e8f25e61576 in client_command_input (cmd=0xe9159845048) at imap-client.c:1204 client = 0xe9159845848 command = <optimized out> tag = <optimized out> ret = <optimized out> name = <optimized out> #36 0x00000e8f25e61682 in client_command_input (cmd=0xe9159845048) at imap-client.c:1269 client = 0xe9159845848 command = <optimized out> tag = <optimized out> ret = <optimized out> name = <optimized out> #37 0x00000e8f25e5ffb4 in client_handle_next_command (client=0xe9159845848, remove_io_r=<optimized out>) at imap-client.c:1313 No locals. #38 client_handle_input (client=0xe9159845848) at imap-client.c:1327 _data_stack_cur_id = <optimized out> handled_commands = false ret = <optimized out> remove_io = <optimized out> #39 0x00000e8f25e5e755 in client_input (client=0xe9159845848) at imap-client.c:1371 output = 0xe92088000a0 bytes = 218 cmd = <optimized out> #40 0x00000e91adc1c851 in io_loop_call_io (io=0xe91eb5d0b00) at ioloop.c:714 ioloop = 0xe9162373d00 t_id = 0 #41 0x00000e91adc1f84c in io_loop_handler_run_internal (ioloop=0xe9162373d00) at ioloop-kqueue.c:164 tv = { tv_sec = 3, tv_usec = 410626 } ts = { tv_sec = 3, tv_nsec = 410626000 } ctx = 0xe9171193980 msecs = <optimized out> events_count = <optimized out> events = <optimized out> ret = <optimized out> i = <optimized out> io = 0xe91eb5d0b00 #42 0x00000e91adc1cfd9 in io_loop_handler_run (ioloop=0xe9162373d00) at ioloop.c:766 No locals. #43 0x00000e91adc1cce8 in io_loop_run (ioloop=0xe9162373d00) at ioloop.c:739 No locals. #44 0x00000e91adb77655 in master_service_run (service=0xe9193c39600, callback=0x6) at master-service.c:853 No locals. #45 0x00000e8f25e70dd1 in main (argc=1, argv=<optimized out>) at main.c:532 set_roots = {0xe91adc66270 , 0xe8f25e7e310 , 0x0} login_set = { auth_socket_path = 0xe9136774490 "HEADER.FIELDS (DATE FROM SENDER SUBJECT TO CC MESSAGE-ID REFERENCES CONTENT-TYPE CONTENT-DESCRIPTION IN-REPLY-TO REPLY-TO LINES LIST-POST X-LABEL)", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0xe8f25e70fc0 , failure_callback = 0xe8f25e712b0 , request_auth_token = true } username = <optimized out> storage_service_flags = <optimized out> service_flags = <optimized out> auth_socket_path = <optimized out> c = <optimized out> error = 0x7f7ffffcea18 "]\353\374\377\177\177" (gdb)