Hi.
tldr; dovecot crashes when moving an email into a Maildir that has the
cur/ sub-directory marked as read-only.
Yesterday I got this in syslog:
Dec 10 23:15:20 uggla dovecot: imap-login: Aborted login (no auth attempts in 0 secs): user=<>, rip=178.174.241.104, lip=178.174.241.107, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
Dec 10 23:15:50 uggla kernel: [1213757.643097] show_signal_msg: 2 callbacks suppressed
Dec 10 23:15:50 uggla kernel: [1213757.643105] imap[1395446]: segfault at 20 ip 00007fd78f75d340 sp 00007ffd1367d0e0 error 4 in libdovecot-storage.so.0.0.0[7fd78f739000+d3000]
Dec 10 23:15:50 uggla kernel: [1213757.652346] Code: 00 00 48 89 44 24 18 48 8d 44 24 30 c7 44 24 14 30 00 00 00 48 89 44 24 20 e8 0c 2f fe ff 48 8d 74 24 10 48 89 ef 89 44 24 0c <f6> 43 20 02 74 4a e8 d5 17 fe ff 48 8b 3b
48 8d 35 fa 12 0b 00 48
Dec 10 23:15:50 uggla systemd[1]: Created slice system-systemd\x2dcoredump.slice.
Dec 10 23:15:50 uggla systemd[1]: Started Process Core Dump (PID 1428343/UID 0).
Dec 10 23:15:50 uggla systemd-coredump[1428344]: Process 1395446 (imap) of user 117 dumped core.#012#012Stack trace of thread 1395446:#012#0 0x00007fd78f75d340 mail_set_critical (libdovecot-storage.so.0 + 0x5b340)#012#1 0x00007fd78f787e42 maildir_file_move (libdovecot-storage.so.0 + 0x85e42)#012#2 0x00007fd78f7e16f5 index_transaction_index_commit (libdovecot-storage.so.0 + 0xdf6f5)#012#3 0x00007fd78f7fc536 mail_index_transaction_commit_full (libdovecot-storage.so.0 + 0xfa536)#012#4 0x00007fd78f7e1c12 index_transaction_commit (libdovecot-storage.so.0 + 0xdfc12)#012#5 0x00007fd78f7bdbb1 index_list_transaction_commit (libdovecot-storage.so.0 + 0xbbbb1)#012#6 0x00007fd78f75fa66 mailbox_transaction_commit_get_changes (libdovecot-storage.so.0 + 0x5da66)#012#7 0x000055908df44fb2 fetch_and_copy (imap + 0x12fb2)#012#8 0x000055908df52bc4 command_exec (imap + 0x20bc4)#012#9 0x000055908df50bbf client_command_input (imap + 0x1ebbf)#012#10 0x000055908df50c6a client_command_input (imap + 0x1ec6a)#012#11 0x000055908df50f1d client_command_input (imap + 0x1ef1d)#012#12 0x000055908df510e5 client_handle_next_command (imap + 0x1f0e5)#012#13 0x000055908df51650 client_input (imap + 0x1f650)#012#14 0x00007fd78f64ff59 io_loop_call_io (libdovecot.so.0 + 0x111f59)#012#15 0x00007fd78f651592 io_loop_handler_run_internal (libdovecot.so.0 + 0x113592)#012#16 0x00007fd78f650000 io_loop_handler_run (libdovecot.so.0 + 0x112000)#012#17 0x00007fd78f6501c0 io_loop_run (libdovecot.so.0 + 0x1121c0)#012#18 0x00007fd78f5c64e3 master_service_run (libdovecot.so.0 + 0x884e3)#012#19 0x000055908df42e76 main (imap + 0x10e76)#012#20 0x00007fd78f399d0a __libc_start_main (libc.so.6 + 0x26d0a)#012#21 0x000055908df42f1a _start (imap + 0x10f1a)
Dec 10 23:15:50 uggla systemd[1]: systemd-coredump@0-1428343-0.service: Succeeded.
Dec 10 23:15:50 uggla dovecot: imap(simon)<1395446><VgzUcNDSWu4gAQmxQaz/AFw+hakKsX6V>: Fatal: master: service(imap): child 1395446 killed with signal 11 (core dumped)
Dec 10 23:15:55 uggla dovecot: imap-login: Login: user=<simon>, method=CRAM-MD5, rip=2001:9b1:41ac:ff00:5c3e:85a9:ab1:7e95, lip=2001:9b1:8633::107, mpid=1428353, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
Dec 10 23:15:55 uggla dovecot: imap(simon)<1428353><y0QUEdLSevAgAQmxQaz/AFw+hakKsX6V>: Logged out in=148 out=9216 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
The first and two last lines are unrelated events but included to show
that nothing else occured exactly at the time this happened.
Since that happened the first time, it happened repeatedly over the next
few hours:
root@uggla:~# coredumpctl list|wc -l
114
root@uggla:~# coredumpctl list
TIME PID UID GID SIG COREFILE EXE
Fri 2021-12-10 23:15:50 CET 1395446 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:11 CET 1424256 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:16 CET 1428364 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:22 CET 1428375 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:38 CET 1428391 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:40 CET 1428399 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:43 CET 1428407 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:16:46 CET 1428418 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:22:51 CET 1428373 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:22:54 CET 1429835 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:22:57 CET 1429846 117 124 11 present /usr/lib/dovecot/imap
Fri 2021-12-10 23:32:45 CET 1429843 117 124 11 present /usr/lib/dovecot/imap
...
Sat 2021-12-11 10:51:04 CET 1620464 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:03:29 CET 1623242 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:03:32 CET 1623252 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:03:35 CET 1623262 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:03:38 CET 1623271 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:03:56 CET 1623281 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:04:12 CET 1623290 117 124 11 present /usr/lib/dovecot/imap
Sat 2021-12-11 11:04:15 CET 1623298 117 124 11 present /usr/lib/dovecot/imap
root@uggla:~#
I can trigger the problem by opening up the iOS 15.2 mail client.
Opening up Evolution, Gnus or some other IMAP client does not trigger
this. Enabling rawlog gives these in "in":
1639218042.880757 2 ID ("name" "iPhone Mail" "version" "19B81" "os" "iOS" "os-version" "15.1.1 (19B81)")
1639218042.885124 3 SELECT INBOX
1639218042.889902 4 UID SEARCH RETURN (COUNT) 1:* DELETED
1639218042.894675 5 NOOP
1639218042.899605 6 UID MOVE 730364 2020
and this in "out":
1639218042.876104 1 OK [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 PREVIEW=FUZZY STATUS=SIZE SAVEDATE LITERAL+ NOTIFY SPECIAL-USE] Logged in
1639218042.880837 * ID ("name" "Dovecot")
1639218042.880853 2 OK ID completed (0.001 + 0.000 secs).
1639218042.885517 * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $has_cal JUNK $Forwarded Forwarded NOTJUNK $label1 $Labelwork)
1639218042.885532 * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $has_cal JUNK $Forwarded Forwarded NOTJUNK $label1 $Labelwork \*)] Flags permitted.
1639218042.885540 * 235 EXISTS
1639218042.885547 * 0 RECENT
1639218042.885554 * OK [UNSEEN 228] First unseen.
1639218042.885561 * OK [UIDVALIDITY 1600769433] UIDs valid
1639218042.885568 * OK [UIDNEXT 737050] Predicted next UID
1639218042.885574 * OK [HIGHESTMODSEQ 59482] Highest
1639218042.885584 3 OK [READ-WRITE] Select completed (0.001 + 0.000 secs).
1639218042.890112 * ESEARCH (TAG "4") UID COUNT 0
1639218042.890252 4 OK Search completed (0.001 + 0.000 secs).
1639218042.894820 5 OK NOOP completed (0.001 + 0.000 secs).
Find a complete backtrace below. All the other backtraces refer to
slightly different files, but all of them have in common that they refer
to the "2020" sub-directory. This gave me the clue to nail down the
cause:
root@uggla:~# ls -la /var/spool/dovecot/simon/Maildir/.2020/
total 21744
drwx------ 5 dovmail dovmail 4096 Dec 11 11:20 .
drwx------ 139 dovmail dovmail 12288 Dec 11 11:20 ..
dr-x------ 2 dovmail dovmail 1302528 Nov 26 21:55 cur
-rw------- 1 dovmail dovmail 102 Jul 5 19:11 dovecot-keywords
-rw------- 1 dovmail dovmail 831889 Nov 26 21:55 dovecot-uidlist
-rw------- 1 dovmail dovmail 10 Dec 11 11:20 dovecot-uidlist.lock
-rw------- 1 dovmail dovmail 360336 Nov 10 15:52 dovecot.index
-rw------- 1 dovmail dovmail 19670648 Dec 9 17:25 dovecot.index.cache
-rw------- 1 dovmail dovmail 24880 Nov 26 21:55 dovecot.index.log
-rw------- 1 dovmail dovmail 0 Sep 22 2020 maildirfolder
drwx------ 2 dovmail dovmail 4096 Dec 30 2020 new
drwx------ 2 dovmail dovmail 20480 Dec 11 11:20 tmp
root@uggla:~#
That is, I have marked the cur/ sub-directory as read-only. My idea was
that I don't want my mail clients to be doing anything to old e-mails,
but apparently I had tried to move an e-mail into that folder anyway.
Doing a chmod -R +w on that directory solved the problem.
I don't think dovecot should crash, but instead just return an error
message that the destination folder is read-only, so I'm reporting this.
Finally: Is there another solution to the problem I had that caused me
to do 'chmod -R -w' on the cur/ sub-directory? I want to mark some
Maildir's as read-only for all my IMAP client. Earlier I tried to mark
the entire Maildir folder but that caused problems because dovecot could
not update the "dovecot.index" files. So I switched to just mark the
cur/ sub-directory as read-only. Maybe that is a proper solution, and
if this crash is fixed to just return an error message to the IMAP
client, all will be fine.
/Simon
root@uggla:~# coredumpctl gdb 1395446
PID: 1395446 (imap)
UID: 117 (dovmail)
GID: 124 (dovmail)
Signal: 11 (SEGV)
Timestamp: Fri 2021-12-10 23:15:50 CET (11h ago)
Command Line: dovecot/imap
Executable: /usr/lib/dovecot/imap
Control Group: /system.slice/dovecot.service
Unit: dovecot.service
Slice: system.slice
Boot ID: 88082b035c894691b07468130a33d453
Machine ID: 74e89ff4f3ad4cbfb3797faa62d4989d
Hostname: uggla
Storage: /var/lib/systemd/coredump/core.imap.117.88082b035c894691b07468130a33d453.1395446.1639174550000000.zst
Message: Process 1395446 (imap) of user 117 dumped core.
Stack trace of thread 1395446:
#0 0x00007fd78f75d340 mail_set_critical (libdovecot-storage.so.0 + 0x5b340)
#1 0x00007fd78f787e42 maildir_file_move (libdovecot-storage.so.0 + 0x85e42)
#2 0x00007fd78f7e16f5 index_transaction_index_commit (libdovecot-storage.so.0 + 0xdf6f5)
#3 0x00007fd78f7fc536 mail_index_transaction_commit_full (libdovecot-storage.so.0 + 0xfa536)
#4 0x00007fd78f7e1c12 index_transaction_commit (libdovecot-storage.so.0 + 0xdfc12)
#5 0x00007fd78f7bdbb1 index_list_transaction_commit (libdovecot-storage.so.0 + 0xbbbb1)
#6 0x00007fd78f75fa66 mailbox_transaction_commit_get_changes (libdovecot-storage.so.0 + 0x5da66)
#7 0x000055908df44fb2 fetch_and_copy (imap + 0x12fb2)
#8 0x000055908df52bc4 command_exec (imap + 0x20bc4)
#9 0x000055908df50bbf client_command_input (imap + 0x1ebbf)
#10 0x000055908df50c6a client_command_input (imap + 0x1ec6a)
#11 0x000055908df50f1d client_command_input (imap + 0x1ef1d)
#12 0x000055908df510e5 client_handle_next_command (imap + 0x1f0e5)
#13 0x000055908df51650 client_input (imap + 0x1f650)
#14 0x00007fd78f64ff59 io_loop_call_io (libdovecot.so.0 + 0x111f59)
#15 0x00007fd78f651592 io_loop_handler_run_internal (libdovecot.so.0 + 0x113592)
#16 0x00007fd78f650000 io_loop_handler_run (libdovecot.so.0 + 0x112000)
#17 0x00007fd78f6501c0 io_loop_run (libdovecot.so.0 + 0x1121c0)
#18 0x00007fd78f5c64e3 master_service_run (libdovecot.so.0 + 0x884e3)
#19 0x000055908df42e76 main (imap + 0x10e76)
#20 0x00007fd78f399d0a __libc_start_main (libc.so.6 + 0x26d0a)
#21 0x000055908df42f1a _start (imap + 0x10f1a)
GNU gdb (Debian 10.1-1.7) 10.1.90.20210103-git
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/lib/dovecot/imap...
Reading symbols from /usr/lib/debug/.build-id/3a/3cf472399f087640eea737261a1772a42414c8.debug...
[New LWP 1395446]
Core was generated by `dovecot/imap'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 mail_set_critical (mail=0x0, fmt=fmt@entry=0x7fd78f813092 "rename(%s, %s) failed: %m") at mail-storage.c:595
595 mail-storage.c: No such file or directory.
(gdb) bt
#0 mail_set_critical (mail=0x0, fmt=fmt@entry=0x7fd78f813092 "rename(%s, %s) failed: %m") at mail-storage.c:595
#1 0x00007fd78f787e42 in maildir_file_move (newdir=false, destname=<optimized out>, mf=0x55908ea7cb60, ctx=0x55908ea7c9b8) at maildir-save.c:108
#2 maildir_save_move_files_to_newcur (ctx=0x55908ea7c9b8) at maildir-save.c:897
#3 maildir_transaction_save_commit_pre (_ctx=0x55908ea7c9b8) at maildir-save.c:1007
#4 0x00007fd78f7e16f5 in index_transaction_index_commit (index_trans=0x55908e9fa5c0, result_r=0x7ffd1367d360) at index-transaction.c:56
#5 0x00007fd78f7fc536 in mail_index_transaction_commit_full (_t=_t@entry=0x7ffd1367d358, result_r=result_r@entry=0x7ffd1367d360) at mail-index-transaction.c:305
#6 0x00007fd78f7e1c12 in index_transaction_commit (t=0x55908ea40660, changes_r=0x7ffd1367d4d0) at index-transaction.c:211
#7 0x00007fd78f7bdbb1 in index_list_transaction_commit (t=0x55908ea40660, changes_r=0x7ffd1367d4d0) at mailbox-list-index-status.c:732
#8 0x00007fd78f75fa66 in mailbox_transaction_commit_get_changes (_t=_t@entry=0x7ffd1367d498, changes_r=changes_r@entry=0x7ffd1367d4d0) at mail-storage.c:2384
#9 0x000055908df44fb2 in fetch_and_copy (search_args=<optimized out>, copy_ctx=0x7ffd1367d500) at cmd-copy.c:129
#10 cmd_copy_full (cmd=0x55908e9d7f18, move=<optimized out>) at cmd-copy.c:232
#11 0x000055908df52bc4 in command_exec (cmd=0x55908e9d7f18) at imap-commands.c:201
#12 0x000055908df50bbf in client_command_input (cmd=<optimized out>) at imap-client.c:1204
#13 0x000055908df50c6a in client_command_input (cmd=<optimized out>) at imap-client.c:1271
#14 0x000055908df50f1d in client_command_input (cmd=<optimized out>) at imap-client.c:1238
#15 0x000055908df510e5 in client_handle_next_command (remove_io_r=<synthetic pointer>, client=0x55908e9d72e8) at imap-client.c:1313
#16 client_handle_input (client=0x55908e9d72e8) at imap-client.c:1327
#17 0x000055908df51650 in client_input (client=0x55908e9d72e8) at imap-client.c:1371
#18 0x00007fd78f64ff59 in io_loop_call_io (io=0x55908e9f5020) at ioloop.c:714
#19 0x00007fd78f651592 in io_loop_handler_run_internal (ioloop=ioloop@entry=0x55908e9b6260) at ioloop-epoll.c:222
#20 0x00007fd78f650000 in io_loop_handler_run (ioloop=0x55908e9b6260) at ioloop.c:766
#21 0x00007fd78f6501c0 in io_loop_run (ioloop=0x55908e9b6260) at ioloop.c:739
#22 0x00007fd78f5c64e3 in master_service_run (service=0x55908e9b60c0, callback=callback@entry=0x55908df5f470 <client_connected>) at master-service.c:853
#23 0x000055908df42e76 in main (argc=<optimized out>, argv=<optimized out>) at main.c:532
(gdb) (gdb) bt full
#0 mail_set_critical (mail=0x0, fmt=fmt@entry=0x7fd78f813092 "rename(%s, %s) failed: %m") at mail-storage.c:595
_data_stack_cur_id = 8
va = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 0x7ffd1367d1e0, reg_save_area = 0x7ffd1367d110}}
#1 0x00007fd78f787e42 in maildir_file_move (newdir=false, destname=<optimized out>, mf=0x55908ea7cb60, ctx=0x55908ea7c9b8) at maildir-save.c:108
storage = 0x55908e9db068
tmp_path = 0x55908e9ada48 "/var/spool/dovecot//simon/Maildir/.2020/tmp/1639174549.M992713P1395446.uggla"
new_path = 0x55908e9ada98 "/var/spool/dovecot//simon/Maildir/.2020/cur/1627647781.M95260P4509.uggla,S=38545,W=39199:2,S"
storage = <optimized out>
tmp_path = <optimized out>
new_path = <optimized out>
__func__ = "maildir_file_move"
#2 maildir_save_move_files_to_newcur (ctx=0x55908ea7c9b8) at maildir-save.c:897
dest = 0x55908e9ad940 "1627647781.M95260P4509.uggla,S=38545,W=39199:2,S"
_data_stack_cur_id = 7
mfp__foreach_end = 0x55908e9ad8e8
files = {arr = {buffer = 0x55908e9ad8a8, element_size = 8}, v = 0x55908e9ad8a8, v_modifiable = 0x55908e9ad8a8}
mfp = 0x55908e9ad8e0
prev_mf = <optimized out>
new_changed = false
cur_changed = true
ret = <optimized out>
mf = 0x55908ea7cb60
newdir = false
files = {arr = {buffer = <optimized out>, element_size = <optimized out>}, v = <optimized out>, v_modifiable = <optimized out>}
mf = <optimized out>
mfp = <optimized out>
prev_mf = <optimized out>
newdir = <optimized out>
new_changed = <optimized out>
cur_changed = <optimized out>
ret = <optimized out>
__func__ = "maildir_save_move_files_to_newcur"
mfp__foreach_end = <optimized out>
_data_stack_cur_id = <optimized out>
dest = <optimized out>
#3 maildir_transaction_save_commit_pre (_ctx=0x55908ea7c9b8) at maildir-save.c:1007
_data_stack_cur_id = 6
ctx = <optimized out>
_t = <optimized out>
sync_flags = <optimized out>
ret = <optimized out>
__func__ = "maildir_transaction_save_commit_pre"
#4 0x00007fd78f7e16f5 in index_transaction_index_commit (index_trans=0x55908e9fa5c0, result_r=0x7ffd1367d360) at index-transaction.c:56
t = 0x55908ea40660
pvt_sync_ctx = 0x0
error = 0x0
ret = 0
__func__ = "index_transaction_index_commit"
#5 0x00007fd78f7fc536 in mail_index_transaction_commit_full (_t=_t@entry=0x7ffd1367d358, result_r=result_r@entry=0x7ffd1367d360) at mail-index-transaction.c:305
t = 0x55908e9fa5c0
index = 0x55908ea934b0
index_undeleted = false
#6 0x00007fd78f7e1c12 in index_transaction_commit (t=0x55908ea40660, changes_r=0x7ffd1367d4d0) at index-transaction.c:211
box = 0x55908ea3df28
itrans = 0x0
result = {log_file_seq = 0, log_file_offset = 0, commit_size = 0, changes_mask = 0, ignored_modseq_changes = 0}
ret = 0
#7 0x00007fd78f7bdbb1 in index_list_transaction_commit (t=0x55908ea40660, changes_r=0x7ffd1367d4d0) at mailbox-list-index-status.c:732
box = 0x55908ea3df28
ibox = <optimized out>
#8 0x00007fd78f75fa66 in mailbox_transaction_commit_get_changes (_t=_t@entry=0x7ffd1367d498, changes_r=changes_r@entry=0x7ffd1367d4d0) at mail-storage.c:2384
_data_stack_cur_id = 5
t = 0x55908ea40660
box = 0x55908ea3df28
save_count = 1
ret = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--q
Quit
(gdb)