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

On 2021/01/28 14:51, Aki Tuomi wrote:

Hi!

Would it be possible for you to provide the mail through obfuscation.

You can use https://dovecot.org/tools/maildir-obfuscate.pl for this purpose.

If you are using maildir format, you can decompress the mail with lz4 decompression tool. If you are using dbox format, it's slightly trickier as you need to remove the container around the mail first, and then decompress it.

It's mdbox (sorry I thought I had mentioned that earlier but seems I missed it).

So here's the tail of output from doveadm -u sthen fetch "uid text" mailbox ports

--snip--snip--snip---------------------- uid: 34088 text: Return-Path: owner-ports+M113360=stu=spacehopper.org@openbsd.org [...]

www/seamonkey Could not find gconf-2.0 -> seems repeatable but I don't understand why py3 would be involved so maybe it's fallout from something else

graphics/vulkan-tools 'time' has no attribute 'clock' -> port is outdated; this was fixed as part doveadm(sthen): Panic: file istream.c: line 332 (i_stream_read_memarea): assertion failed: (!stream->blocking) --snip--snip--snip----------------------

The actual message has a few more lines, it's a public list post so I can compare 'doveadm fetch -u sthen "uid text" mailbox ports uid 34088' against https://marc.info/?l=openbsd-ports&m=159372656616988&q=raw and see that it is fetched completely.

So, on to extracting the compressed mail, and this might give some clues:

$ doveadm -o mail_plugins=virtual fetch -u sthen text mailbox ports uid 34088 > 34088.z doveadm(sthen): Error: Mailbox ports: Deleting corrupted cache record uid=34088: UID 34088: Broken physical size in mailbox ports: read(/home/sthen/mdbox/storage/m.6167) failed: Cached message size larger than expected (8851 > 4542, box=ports, UID=34088) doveadm(sthen): Error: read(/home/sthen/mdbox/storage/m.6167) failed: Cached message size larger than expected (8851 > 4542, box=ports, UID=34088) doveadm(sthen): Error: fetch(text) failed for box=ports uid=34088: read(/home/sthen/mdbox/storage/m.6167) failed: Cached message size larger than expected (8851 > 4542, box=ports, UID=34088)

$ tail -n +2 34088.z > 34088.zz $ doveadm fs get compress lz4:0:posix 34088.zz > plain ..and (not surprising since the message is displayed OK with "fetch ... uid") the complete message is there..

If I try fetching that message again I no longer see the "Deleting corrupted cache record" but I do still get a crash at the same point if I fetch text for the whole mailbox.

Looking at the visible bits in that mdbox file I don't think I will be able to identify the various correspondents enough to get their permission to provide the whole file. (The list mail is public anyway, but from what I can make out past the lz4 there's at least some private mail in the file). But happy to dig around in there if there's anything that might help, I can be /m'd on freenode (sthen) if real- time is better for that.

Aki

...

On 28/01/2021 14:45 Stuart Henderson stu@spacehopper.org wrote:

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)