dovecot/imap killed with signal 6 after SEARCH in specific mailbox
Hi All, on my older production server (Deb9 dovecot version 2.2.27-3+deb9u6) a client reported that searching text in one mailbox failed while other mailboxes do search ok. He is using Rouddcube webmail and is searching the whole messages including the body. Errorlog shows panic and assertion failed logs. So I'v moved the 'problematic' mailbox to my latest production server (Deb10 2.3.4.1-5+deb10u4 = 2.3.4.1 (f79e8e7e4)) where I have more RAM to eliminate that and the same error appeared. There is nothing special about the mailbox, roughly 600MiB and 2200 messges. Other much larger mailboxes on the same server do search fine. After turning on imap logging in Roundcube mail, the critical command was: A0004 UID SEARCH RETURN (ALL) TEXT whatever I increased default_process_limit and default_client_limit, I run: doveadm index -u ttt@mail2.swpraha.cz -q INBOX but didn't help.
I used the gdb method to reproduce it and to get the whole info including backtrace:
vmail@s6mail:~$ gdb --args /usr/lib/dovecot/imap -u ttt@mail2.swpraha.cz (gdb) r Starting program: /usr/lib/dovecot/imap -u ttt@mail2.swpraha.cz process 4458 is executing new program: /usr/bin/doveconf process 4458 is executing new program: /usr/lib/dovecot/imap
- PREAUTH [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in as ttt@mail2.swpraha.cz a select INBOX
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk $Forwarded NonJunk)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk $Forwarded NonJunk \*)] Flags permitted.
- 682 EXISTS
- 0 RECENT
- OK [UNSEEN 639] First unseen.
- OK [UIDVALIDITY 1147771637] UIDs valid
- OK [UIDNEXT 104487] Predicted next UID
- OK [HIGHESTMODSEQ 53108] Highest a OK [READ-WRITE] Select completed (0.002 + 0.000 + 0.001 secs). A0004 UID SEARCH RETURN (ALL) TEXT whatewer imap(ttt@mail2.swpraha.cz)<4458><Auy4NnMnzl9qEQAAevFY8w>: Panic: file message-parser.c: line 174 (message_part_finish): assertion failed: (ctx->nested_parts_count > 0) imap(ttt@mail2.swpraha.cz)<4458><Auy4NnMnzl9qEQAAevFY8w>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xdb62b) [0x7ffff7dbb62b] -> /usr/lib/dovecot/libdovecot.so.0(+0xdb661) [0x7ffff7dbb661] -> /usr/lib/dovecot/libdovecot.so.0(+0x4a149) [0x7ffff7d2a149] -> /usr/lib/dovecot/libdovecot.so.0(+0x474ac) [0x7ffff7d274ac] -> /usr/lib/dovecot/libdovecot.so.0(message_parser_parse_next_block+0x104) [0x7ffff7da3844] -> /usr/lib/dovecot/libdovecot.so.0(message_search_msg+0xa8) [0x7ffff7da5df8] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xcf89e) [0x7ffff7f3e89e] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_search_args_foreach+0x45) [0x7ffff7ec0445] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xd0774) [0x7ffff7f3f774] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xd1a68) [0x7ffff7f40a68] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblock+0x10d) [0x7ffff7f4118d] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_search_next_nonblock+0x28) [0x7ffff7ec9e58] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x55555557a91f] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555573d80] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555579ed2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0x111) [0x7ffff7dd18f1] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd0) [0x7ffff7dd3070] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4c) [0x7ffff7dd1b7c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x40) [0x7ffff7dd1ce0] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7ffff7d520d3] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555564bf5] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7ffff7b3c09b] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555564d8a]
Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt full
#0 __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:50
set = {__val = {0, 9355454118400172544, 1928, 1862, 1863,
93824992506008, 65, 140737352109185, 140737351192526, 140737351951989,
257, 145, 206158430224, 140737488344944, 140737488344736,
140737351756174}}
pid = <optimized out>
tid = <optimized out>
ret = <optimized out>
#1 0x00007ffff7b3a535 in __GI_abort () at abort.c:79
save_stage = 1
act = {__sigaction_handler = {sa_handler = 0x9ef, sa_sigaction =
0x9ef}, sa_mask = {__val = {30216, 93824992300426, 0, 513, 513,
140737351192526, 140737351744763, 140737351192526, 9355454118400172544,
140737351192526, 140737351951234, 140737488344944,
93824992503880, 140737351192526, 140737351951609, 140737351192526}},
sa_flags = -136625910, sa_restorer = 0x5}
sigs = {__val = {32, 0
========================== dovecot -n: # 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.4 () # OS: Linux 5.4.65-1-pve x86_64 Debian 10.6 # Hostname: s6mail.ehosting.cz default_client_limit = 10000 default_process_limit = 1000 deliver_log_format = msgid=%m, from=%f, Subj=%s: %$ dict { expire = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext quota = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext } disable_plaintext_auth = no first_valid_gid = 150 first_valid_uid = 150 last_valid_gid = 150 last_valid_uid = 150 log_timestamp = "%Y-%m-%d %H:%M:%S " mail_plugins = quota trash expire mail_privileged_group = vmail 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 spamtest spamtestplus namespace inbox { inbox = yes location = mailbox Archive { auto = subscribe special_use = \Archive } mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { auto = subscribe special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { auto = subscribe special_use = \Trash } prefix = separator = / } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { antispam_backend = pipe antispam_crm_binary = /bin/false antispam_dspam_args = --deliver=;--user;%u;--source=error;--signature=%%s antispam_dspam_binary = /usr/bin/dspam antispam_dspam_notspam = --class=innocent antispam_dspam_result_header = X-DSPAM-Result antispam_dspam_spam = --class=spam antispam_pipe_program = /usr/local/bin/postfix/reclasify-from-dovecot antispam_pipe_program_args = %u;%d antispam_pipe_program_notspam_arg = --ham antispam_pipe_program_spam_arg = --spam antispam_pipe_tmpdir = /tmp antispam_signature = X-CRM114-CacheID antispam_signature_missing = error antispam_spam = Junk;Spam antispam_spool2dir_notspam = /tmp/spamspool/%%020lu-%u-%%05luh antispam_spool2dir_spam = /tmp/spamspool/%%020lu-%u-%%05lus antispam_trash = trash;Trash;Deleted Items;Deleted Messages antispam_verbose_debug = 0 expire = Trash expire2 = Trash/* expire3 = Spam expire_dict = proxy::expire quota = dict:User quota::proxy::quota quota_exceeded_message = Uzivatel %u ma zaplnenou schranku. quota_rule = *:storage=1G quota_rule2 = Trash:storage=+100M sieve = file:~/sieve;active=~/.dovecot.sieve sieve_after = /etc/dovecot/sieve_after sieve_before = /etc/dovecot/sieve_before sieve_extensions = +spamtest +spamtestplus sieve_spamtest_max_value = 15 sieve_spamtest_status_header = X-Spam-Level sieve_spamtest_status_type = strlen trash = /etc/dovecot/dovecot-trash.conf.ext } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_uidl_format = UID%u-%v postmaster_address = sysadmin@ehosting.cz protocols = " imap lmtp sieve pop3" service auth-worker { user = $default_internal_user } service dict { unix_listener dict { user = vmail } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } user = vmail } service stats { unix_listener stats-writer { user = vmail } } ssl_cert =
==========================
The dovecot.err shows the two mentioned error lines (Panic:, Error:) plus: Dec 7 13:12:21 s6mail dovecot: imap(ttt@mail2.swpraha.cz)<13466><wezwvN61RK0AAAAAAAAAAAAAAAAAAAAB>: Fatal: master: service(imap): child 13466 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps) Please let me know if you need any other details.
Thanks for any suggestion --Jiri Kacena
On 07/12/2020 16:58, Jiri wrote:
Hi All, on my older production server (Deb9 dovecot version 2.2.27-3+deb9u6) a client reported that searching text in one mailbox failed while other mailboxes do search ok. He is using Rouddcube webmail and is searching the whole messages including the body. Errorlog shows panic and assertion failed logs. So I'v moved the 'problematic' mailbox to my latest production server (Deb10 2.3.4.1-5+deb10u4 = 2.3.4.1 (f79e8e7e4)) where I have more RAM to eliminate that and the same error appeared. There is nothing special about the mailbox, roughly 600MiB and 2200 messges. Other much larger mailboxes on the same server do search fine. After turning on imap logging in Roundcube mail, the critical command was: A0004 UID SEARCH RETURN (ALL) TEXT whatever I increased default_process_limit and default_client_limit, I run: doveadm index -u ttt@mail2.swpraha.cz -q INBOX but didn't help.
I used the gdb method to reproduce it and to get the whole info including backtrace:
vmail@s6mail:~$ gdb --args /usr/lib/dovecot/imap -u ttt@mail2.swpraha.cz (gdb) r Starting program: /usr/lib/dovecot/imap -u ttt@mail2.swpraha.cz process 4458 is executing new program: /usr/bin/doveconf process 4458 is executing new program: /usr/lib/dovecot/imap
- PREAUTH [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in as ttt@mail2.swpraha.cz a select INBOX
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk $Forwarded NonJunk)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk $Forwarded NonJunk \*)] Flags permitted.
- 682 EXISTS
- 0 RECENT
- OK [UNSEEN 639] First unseen.
- OK [UIDVALIDITY 1147771637] UIDs valid
- OK [UIDNEXT 104487] Predicted next UID
- OK [HIGHESTMODSEQ 53108] Highest a OK [READ-WRITE] Select completed (0.002 + 0.000 + 0.001 secs). A0004 UID SEARCH RETURN (ALL) TEXT whatewer imap(ttt@mail2.swpraha.cz)<4458><Auy4NnMnzl9qEQAAevFY8w>: Panic: file message-parser.c: line 174 (message_part_finish): assertion failed: (ctx->nested_parts_count > 0) imap(ttt@mail2.swpraha.cz)<4458><Auy4NnMnzl9qEQAAevFY8w>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xdb62b) [0x7ffff7dbb62b] -> /usr/lib/dovecot/libdovecot.so.0(+0xdb661) [0x7ffff7dbb661] -> /usr/lib/dovecot/libdovecot.so.0(+0x4a149) [0x7ffff7d2a149] -> /usr/lib/dovecot/libdovecot.so.0(+0x474ac) [0x7ffff7d274ac] -> /usr/lib/dovecot/libdovecot.so.0(message_parser_parse_next_block+0x104) [0x7ffff7da3844] -> /usr/lib/dovecot/libdovecot.so.0(message_search_msg+0xa8) [0x7ffff7da5df8] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xcf89e) [0x7ffff7f3e89e] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_search_args_foreach+0x45) [0x7ffff7ec0445] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xd0774) [0x7ffff7f3f774] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xd1a68) [0x7ffff7f40a68] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblock+0x10d) [0x7ffff7f4118d] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_search_next_nonblock+0x28) [0x7ffff7ec9e58] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x55555557a91f] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555573d80] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555579ed2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0x111) [0x7ffff7dd18f1] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd0) [0x7ffff7dd3070] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4c) [0x7ffff7dd1b7c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x40) [0x7ffff7dd1ce0] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7ffff7d520d3] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555564bf5] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7ffff7b3c09b] -> /usr/lib/dovecot/imap ttt@mail2.swpraha.cz UID SEARCH [0x555555564d8a]
Program received signal SIGABRT, Aborted. __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb) bt full #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 set = {__val = {0, 9355454118400172544, 1928, 1862, 1863, 93824992506008, 65, 140737352109185, 140737351192526, 140737351951989, 257, 145, 206158430224, 140737488344944, 140737488344736, 140737351756174}} pid = <optimized out> tid = <optimized out> ret = <optimized out> #1 0x00007ffff7b3a535 in __GI_abort () at abort.c:79 save_stage = 1 act = {__sigaction_handler = {sa_handler = 0x9ef, sa_sigaction = 0x9ef}, sa_mask = {__val = {30216, 93824992300426, 0, 513, 513, 140737351192526, 140737351744763, 140737351192526, 9355454118400172544, 140737351192526, 140737351951234, 140737488344944, 93824992503880, 140737351192526, 140737351951609, 140737351192526}}, sa_flags = -136625910, sa_restorer = 0x5} sigs = {__val = {32, 0
}} #2 0x00007ffff7d2a481 in ?? () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #3 0x00007ffff7dbb661 in default_fatal_handler () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #4 0x00007ffff7d2a149 in i_panic () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #5 0x00007ffff7d274ac in ?? () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #6 0x00007ffff7da3844 in message_parser_parse_next_block () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #7 0x00007ffff7da5df8 in message_search_msg () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #8 0x00007ffff7f3e89e in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #9 0x00007ffff7ec0445 in mail_search_args_foreach () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #10 0x00007ffff7f3f774 in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #11 0x00007ffff7f40a68 in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #12 0x00007ffff7f4118d in index_storage_search_next_nonblock () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #13 0x00007ffff7ec9e58 in mailbox_search_next_nonblock () from /usr/lib/dovecot/libdovecot-storage.so.0 No symbol table info available. #14 0x000055555557a91f in ?? () No symbol table info available. #15 0x0000555555573d80 in command_exec () No symbol table info available. #16 0x0000555555579ed2 in ?? () No symbol table info available. #17 0x00007ffff7dd18f1 in io_loop_handle_timeouts () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #18 0x00007ffff7dd3070 in io_loop_handler_run_internal () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #19 0x00007ffff7dd1b7c in io_loop_handler_run () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #20 0x00007ffff7dd1ce0 in io_loop_run () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #21 0x00007ffff7d520d3 in master_service_run () from /usr/lib/dovecot/libdovecot.so.0 No symbol table info available. #22 0x0000555555564bf5 in main () No symbol table info available. (gdb) <snip> Thanks for any suggestion --Jiri Kacena
Looks like this (or something very similar) was already fixed
https://github.com/dovecot/core/commit/a668d767a710ca18ab6e7177d8e8be22a6b02...
John
Dne 2020-12-07 17:06, John Fawcett napsal:
On 07/12/2020 16:58, Jiri wrote:
Hi All, on my older production server (Deb9 dovecot version 2.2.27-3+deb9u6) a client reported that searching text in one mailbox failed while other mailboxes do search ok. He is using Rouddcube webmail and is searching the whole messages including the body. Errorlog shows panic and assertion failed logs. So I'v moved the 'problematic' mailbox to my latest production server (Deb10 2.3.4.1-5+deb10u4 = 2.3.4.1 (f79e8e7e4)) where I have more RAM to eliminate that and the same error appeared. There is nothing special about the mailbox, roughly 600MiB and 2200 messges. Other much larger mailboxes on the same server do search fine. After turning on imap logging in Roundcube mail, the critical command was: A0004 UID SEARCH RETURN (ALL) TEXT whatever I increased default_process_limit and default_client_limit, I run: doveadm index -u ttt@mail2.swpraha.cz -q INBOX but didn't help.
I used the gdb method to reproduce it and to get the whole info including backtrace:
vmail@s6mail:~$ gdb --args /usr/lib/dovecot/imap -u ttt@mail2.swpraha.cz (gdb) r <snip>
<snip> Thanks for any suggestion --Jiri Kacena
Looks like this (or something very similar) was already fixed
https://github.com/dovecot/core/commit/a668d767a710ca18ab6e7177d8e8be22a6b02...
John
Thanks John, your answer was helpful. It was the malformed boundary indeed. Before the fix gets to Debian, I had to manually locate the 'poisoned' message and fix the last boundary line.
--Jiri
participants (2)
-
Jiri
-
John Fawcett