[Dovecot] imap process and indexer-worker crash while creating folders
Hi,
our dovecot processes sometimes crash when we create new folders. The "imap" process and the "indexer worker" process is crashing. We can reproduce this, we have a java program with multiple threads, and sometimes 2 threads try to create the same folder for the same user, and if both collide, dovecot processes crash.
We don't see this happening in the real world if "normal" imap clients are connected, but our special java program trying to create folders in parallel is producing these crashes.
Below you can see the log entries and gdb "bt full" output, one for an "imap" process and one for an "indexer worker" process.
We are using dovecot 2.2.9, and I did not find anything in the changelog regarding this problem. Does ist make sense to try the newest version 2.2.12?
Thanks Michael
================== Apr 1 19:58:28 dovecot01 dovecot: imap(user@domain.de): Panic: file mail-index-transaction-export.c: line 117 (log_append_ext_intro): assertion failed: (intro->ext_id == idx || idx == (uint32_t)-1) Apr 1 19:58:28 dovecot01 dovecot: imap(user@domain.de): Error: Raw backtrace: /usr/local/lib/dovecot/libdovecot.so.0(+0x66ab1) [0x7f0028259ab1] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x66b8e) [0x7f0028259b8e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f00282153ce] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0xb9c72) [0x7f002857ec72] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_export+0x200) [0x7f002857f140] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0xb932f) [0x7f002857e32f] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit_full+0x9d) [0x7f002857e78d] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit+0xc) [0x7f002857e82c] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x3e1ea) [0x7f00285031ea] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x3e44c) [0x7f002850344c] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x90a15) [0x7f0028555a15] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_get_metadata+0x95) [0x7f0028542345] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync_name+0x2a4) [0x7f0028556324] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync+0x10a) [0x7f002855694a] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_refresh+0x9e) [0x7f002855184e] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_iter_init+0x129) [0x7f0028553169] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_iter_init_multiple+0x29) [0x7f0028556ec9] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x93179) [0x7f0028558179] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x91baf) [0x7f0028556baf] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_iter_next+0x334) [0x7f00285577c4] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x40f089] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x40f8ce] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x416adc] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x415b3f] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x415bf5] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x415ef5] -> dovecot/imap user@domain.de 10.0.121.43 LIST [0x416282] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x27) [0x7f0028269a87] Apr 1 19:58:28 dovecot01 dovecot: imap(user@domain.de): Fatal: master: service(imap): child 3928 killed with signal 6 (core dumped)
Core was generated by `dovecot/imap'. Program terminated with signal 6, Aborted. #0 0x00007f0027e61f77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb) bt full #0 0x00007f0027e61f77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 resultvar = 0 pid = 3928 selftid = 3928 #1 0x00007f0027e655e8 in __GI_abort () at abort.c:90 save_stage = 2 act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {11509168, 0, 139638656126069, 1, 0, 4283381, 139638645923048, 140736983670273, 0, 11764224, 139638656153381, 0, 139638646863616, 139638652804256, 11513608, 140736983669916}}, sa_flags = 4096, sa_restorer = 0x7f0027e79134 } sigs = {__val = {32, 0 }} #2 0x00007f0028259ad8 in default_fatal_finish (type=, status=status@entry=0) at failures.c:192 backtrace = 0xaf9eb8 "/usr/local/lib/dovecot/libdovecot.so.0(+0x66ab1) [0x7f0028259ab1] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x66b8e) [0x7f0028259b8e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f0028215"... #3 0x00007f0028259b8e in i_internal_fatal_handler (ctx=0x7fffe1eb1e30, format=, args=) at failures.c:653 status = 0 #4 0x00007f00282153ce in i_panic (format=format@entry=0x7f0028597088 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:264 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fffe1eb1f20, reg_save_area = 0x7fffe1eb1e60}} #5 0x00007f002857ec72 in log_append_ext_intro (ctx=ctx@entry=0x7fffe1eb2040, ext_id=ext_id@entry=5, reset_id=0, hdr_size_r=hdr_size_r@entry=0x7fffe1eb2018) at mail-index-transaction-export.c:117 t = 0xb3dd30 intro = 0xb3cd04 resizes = 0xb3cca0 buf = 0xaf9db0 idx = 0 count = 6 __FUNCTION__ = "log_append_ext_intro" #6 0x00007f002857f140 in mail_transaction_log_append_ext_intros (ctx=0x7fffe1eb2040) at mail-index-transaction-export.c:283 resize = ext_reset = {new_reset_id = 0, preserve_data = 0 '\000', unused_padding = "\000\000"} resize_count = ext_count = 6 hdrs = hdrs_count = 6 ext_id = 5 reset_count = 0 hdr_size = 0 reset = 0x0 reset_buf = {data = 0x7fffe1eb2020, used = 8, priv = {0x7fffe1eb2020, 0x0, 0x8, 0x0, 0x0}} t = reset_id_count = 0 reset_id = reset_ids = 0x0 #7 mail_index_transaction_export (t=t@entry=0xb3dd30, append_ctx=0xb43570) at mail-index-transaction-export.c:409 null4 = "\000\000\000" change_mask = (unknown: 0) ctx = {trans = 0xb3dd30, append_ctx = 0xb43570} __FUNCTION__ = "mail_index_transaction_export" #8 0x00007f002857e32f in mail_index_transaction_commit_real (commit_size_r=0x7fffe1eb2180, t=0xb3dd30) at mail-index-transaction.c:165 _data_stack_cur_id = 7 ctx = 0xb43570 log_seq2 = 0 log_offset1 = 0 log = 0xb38e00 trans_flags = ---Type to continue, or q to quit--- log_seq1 = 11763008 log_offset2 = 7 #9 mail_index_transaction_commit_v (t=0xb3dd30, result_r=0x7fffe1eb2170) at mail-index-transaction.c:203 index = 0xb37d40 changed = true ret = __FUNCTION__ = "mail_index_transaction_commit_v" #10 0x00007f002857e78d in mail_index_transaction_commit_full (_t=_t@entry=0x7fffe1eb21b0, result_r=result_r@entry=0x7fffe1eb2170) at mail-index-transaction.c:262 t = 0xb3dd30 index = 0xb37d40 index_undeleted = false #11 0x00007f002857e82c in mail_index_transaction_commit (t=t@entry=0x7fffe1eb21b0) at mail-index-transaction.c:236 result = {log_file_seq = 0, log_file_offset = 0, commit_size = 0, ignored_modseq_changes = 0} #12 0x00007f00285031ea in mdbox_write_index_header (box=box@entry=0xb37170, update=update@entry=0x0, trans=0xb3dd30, trans@entry=0x0) at mdbox-storage.c:312 mbox = 0xb37170 new_trans = 0x0 view = 0x0 hdr = 0xb39350 uid_validity = 1306175967 uid_next = 0 #13 0x00007f002850344c in mdbox_mailbox_get_guid (guid_r=0x7fffe1eb2370 "", mbox=0xb37170) at mdbox-storage.c:391 need_resize = true ret = 0 idx_hdr = hdr = {map_uid_validity = 0, mailbox_guid = '\000' , flags = 0 '\000', unused = "\000\000"} #14 mdbox_mailbox_get_metadata (box=0xb37170, items=, metadata_r=0x7fffe1eb2370) at mdbox-storage.c:411 items = metadata_r = 0x7fffe1eb2370 box = 0xb37170 mbox = 0xb37170 #15 0x00007f0028555a15 in index_list_get_metadata (box=0xb37170, items=MAILBOX_METADATA_GUID, metadata_r=0x7fffe1eb2370) at mailbox-list-index-status.c:202 ibox = 0xb37a70 #16 0x00007f0028542345 in mailbox_get_metadata (box=0xb37170, items=items@entry=MAILBOX_METADATA_GUID, metadata_r=metadata_r@entry=0x7fffe1eb2370) at mail-storage.c:1544 __FUNCTION__ = "mailbox_get_metadata" #17 0x00007f0028556324 in node_lookup_guid (ctx=, guid_r=0x7fffe1eb2358 "", node=0xb22780) at mailbox-list-index-sync.c:25 box = 0xb37170 vname = str = 0xaf9920 ns_sep = metadata = {guid = '\000' , virtual_size = 0, cache_fields = 0x0, precache_fields = (unknown: 0), backend_ns_prefix = 0x0, backend_ns_type = (unknown: 0)} #18 node_add_to_index (seq_r=0x7fffe1eb2330, node=0xb22780, ctx=0xb34ef0) at mailbox-list-index-sync.c:45 _data_stack_cur_id = 6 irec = {name_id = 65, parent_uid = 0, guid = '\000' , uid_validity = 0} seq = 11759984 #19 mailbox_list_index_node_add (seq_r=0x7fffe1eb2330, name=, parent=, ctx=0xb34ef0) at mailbox-list-index-sync.c:87 node = 0xb22780 dup_name = 0xb227b0 "GoogleMail 01.04.2014 19:58" #20 mailbox_list_index_sync_name (ctx=ctx@entry=0xb34ef0, name=, node_r=node_r@entry=0x7fffe1eb2418, created_r=created_r@entry=0x7fffe1eb240b) at mailbox-list-index-sync.c:125 path = 0xaf9808 empty_path = {0x7f00285982ff "", 0x0} node = parent = i = 0 seq = 0 ---Type to continue, or q to quit--- __FUNCTION__ = "mailbox_list_index_sync_name" #21 0x00007f002855694a in mailbox_list_index_sync_list (sync_ctx=0xb34ef0) at mailbox-list-index-sync.c:318 name = _data_stack_cur_id = 5 iter = 0xb352c0 info = 0xb35340 flags = (unknown: 0) node = 0xb21c40 seq = patterns = {0x7f00285a55d3 "*", 0x0} created = false #22 mailbox_list_index_sync (list=list@entry=0xb15df0) at mailbox-list-index-sync.c:390 sync_ctx = 0xb34ef0 ret = 0 #23 0x00007f002855184e in mailbox_list_index_refresh (list=0xb15df0) at mailbox-list-index.c:380 ilist = 0xb16288 view = 0xb27890 ret = #24 0x00007f0028553169 in iter_use_index (ctx=0xb26dc0, ctx=0xb26dc0) at mailbox-list-index-iter.c:25 ilist = 0xb16288 #25 mailbox_list_index_iter_init (list=0xb15df0, patterns=0xb26c88, flags=(MAILBOX_LIST_ITER_RETURN_CHILDREN | MAILBOX_LIST_ITER_RETURN_SPECIALUSE)) at mailbox-list-index-iter.c:52 ilist = 0xb16288 ctx = 0xb26dc0 pool = 0xb26da0 ns_sep = #26 0x00007f0028556ec9 in mailbox_list_iter_init_multiple (list=0xb15df0, patterns=, flags=(MAILBOX_LIST_ITER_RETURN_CHILDREN | MAILBOX_LIST_ITER_RETURN_SPECIALUSE)) at mailbox-list-iter.c:173 ctx = ret = 0 #27 0x00007f0028558179 in mailbox_list_ns_iter_try_next (info_r=, _ctx=0xb269b0) at mailbox-list-iter.c:574 ctx = 0xb269b0 info = errstr = has_children = ns = error = MAIL_ERROR_NONE #28 mailbox_list_ns_iter_next (_ctx=0xb269b0) at mailbox-list-iter.c:645 info = #29 0x00007f0028556baf in mailbox_list_iter_next_call (ctx=ctx@entry=0xb269b0) at mailbox-list-iter.c:941 info = set = #30 0x00007f00285577c4 in mailbox_list_iter_next (ctx=0xb269b0) at mailbox-list-iter.c:1012 _data_stack_cur_id = 4 info = #31 0x000000000040f089 in cmd_list_continue (cmd=cmd@entry=0xb24190) at cmd-list.c:229 ctx = 0xb242a8 info = flags = str = 0xaf93a0 mutf7_name = 0xaf94f0 name = ret = #32 0x000000000040f8ce in cmd_list_full (cmd=0xb24190, lsub=) at cmd-list.c:463 client = args = 0xb04a98 ---Type to continue, or q to quit--- list_args = 0x0 arg_count = 32512 ctx = 0xb242a8 patterns = {arr = {buffer = 0xb24300, element_size = 8}, v = 0xb24300, v_modifiable = 0xb24300} ref = 0xb242d8 "" pattern = 0xb242e0 "GoogleMail 01.04.2014 19:58" str = #33 0x0000000000416adc in command_exec (cmd=0xb24190) at imap-commands.c:158 hook = 0xb020f0 ret = #34 0x0000000000415b3f in client_command_input (cmd=0xb24190) at imap-client.c:780 client = 0xb235b0 command = __FUNCTION__ = "client_command_input" #35 0x0000000000415bf5 in client_command_input (cmd=0xb24190) at imap-client.c:841 client = 0xb235b0 command = __FUNCTION__ = "client_command_input" #36 0x0000000000415ef5 in client_handle_next_command (remove_io_r=, client=0xb235b0) at imap-client.c:879 No locals. #37 client_handle_input (client=client@entry=0xb235b0) at imap-client.c:891 _data_stack_cur_id = 3 remove_io = false handled_commands = false __FUNCTION__ = "client_handle_input" #38 0x0000000000416282 in client_input (client=0xb235b0) at imap-client.c:933 cmd = 0xb16a70 output = 0xb23fe0 bytes = 42 __FUNCTION__ = "client_input" #39 0x00007f0028269a87 in io_loop_call_io (io=0xb240b0) at ioloop.c:388 ioloop = 0xb01730 t_id = 2 #40 0x00007f002826a817 in io_loop_handler_run (ioloop=ioloop@entry=0xb01730) at ioloop-epoll.c:220 ctx = 0xb023d0 list = 0xb03e00 io = tv = {tv_sec = 1799, tv_usec = 999837} events_count = msecs = ret = 1 i = 0 call = __FUNCTION__ = "io_loop_handler_run" #41 0x00007f0028269628 in io_loop_run (ioloop=0xb01730) at ioloop.c:412 __FUNCTION__ = "io_loop_run" #42 0x00007f002821a5c3 in master_service_run (service=0xb015c0, callback=callback@entry=0x41ec00 ) at master-service.c:566 No locals. #43 0x000000000040b03f in main (argc=1, argv=0xb01390) at main.c:400 set_roots = {0x4269a0 , 0x0} login_set = {auth_socket_path = 0xaf9058 "(", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x41efb0 , failure_callback = 0x41ece0 , request_auth_token = 1} service_flags = storage_service_flags = username = 0x0 ---Type to continue, or q to quit--- c =
Apr 1 20:19:42 dovecot01 dovecot: indexer-worker(user@domain.de): Panic: file mail-index-transaction-export.c: line 117 (log_append_ext_intro): assertion failed: (intro->ext_id == idx || idx == (uint32_t)-1) Apr 1 20:19:42 dovecot01 dovecot: indexer-worker(user@domain.de): Error: Raw backtrace: /usr/local/lib/dovecot/libdovecot.so.0(+0x66ab1) [0x7f77b4f2aab1] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x66b8e) [0x7f77b4f2ab8e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f77b4ee63ce] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0xb9c72) [0x7f77b524fc72] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_export+0x200) [0x7f77b5250140] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0xb932f) [0x7f77b524f32f] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit_full+0x9d) [0x7f77b524f78d] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit+0xc) [0x7f77b524f82c] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x3e1ea) [0x7f77b51d41ea] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x3e44c) [0x7f77b51d444c] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x90a15) [0x7f77b5226a15] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_get_metadata+0x95) [0x7f77b5213345] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync_name+0x2a4) [0x7f77b5227324] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync+0x10a) [0x7f77b522794a] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_refresh+0x9e) [0x7f77b522284e] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x9072e) [0x7f77b522672e] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(+0x909a3) [0x7f77b52269a3] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_sync_deinit+0x22) [0x7f77b5211ef2] -> /usr/local/lib/dovecot/libdovecot-storage.so.0(mailbox_sync+0x39) [0x7f77b5211fa9] -> dovecot/indexer-worker user@domain.de INBOX [0x4022f7] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x27) [0x7f77b4f3aa87] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0xd7) [0x7f77b4f3b817] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f77b4f3a628] -> /usr/local/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f77b4eeb5c3] -> dovecot/indexer-worker user@domain.de INBOX [0x401f03] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f77b4b1dde5] -> dovecot/indexer-worker user@domain.de INBOX [0x401fc2] Apr 1 20:19:42 dovecot01 dovecot: indexer: Error: Indexer worker disconnected, discarding 1 requests for user@domain.de Apr 1 20:19:42 dovecot01 dovecot: indexer-worker(user@domain.de): Fatal: master: service(indexer-worker): child 8806 killed with signal 6 (core dumped)
Core was generated by `dovecot/indexer-worker'. Program terminated with signal 6, Aborted. #0 0x00007f77b4b32f77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb) bt full #0 0x00007f77b4b32f77 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 resultvar = 0 pid = 8806 selftid = 8806 #1 0x00007f77b4b365e8 in __GI_abort () at abort.c:90 save_stage = 2 act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {12654816, 0, 140152119483509, 140149077835777, 0, 4202243, 140152109280488, 140733744696321, 0, 12801792, 140152119510821, 0, 140152110221056, 140152116161696, 12659256, 140733744696092}}, sa_flags = 4096, sa_restorer = 0x7f77b4b4a134 } sigs = {__val = {32, 0 }} #2 0x00007f77b4f2aad8 in default_fatal_finish (type=, status=status@entry=0) at failures.c:192 backtrace = 0xc119e8 "/usr/local/lib/dovecot/libdovecot.so.0(+0x66ab1) [0x7f77b4f2aab1] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x66b8e) [0x7f77b4f2ab8e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f77b4ee6"... #3 0x00007f77b4f2ab8e in i_internal_fatal_handler (ctx=0x7fff20dc4cb0, format=, args=) at failures.c:653 status = 0 #4 0x00007f77b4ee63ce in i_panic (format=format@entry=0x7f77b5268088 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:264 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fff20dc4da0, reg_save_area = 0x7fff20dc4ce0}} #5 0x00007f77b524fc72 in log_append_ext_intro (ctx=ctx@entry=0x7fff20dc4ec0, ext_id=ext_id@entry=5, reset_id=0, hdr_size_r=hdr_size_r@entry=0x7fff20dc4e98) at mail-index-transaction-export.c:117 t = 0xc6d700 intro = 0xc6dac4 resizes = 0xc6da60 buf = 0xc118e0 idx = 0 count = 6 __FUNCTION__ = "log_append_ext_intro" #6 0x00007f77b5250140 in mail_transaction_log_append_ext_intros (ctx=0x7fff20dc4ec0) at mail-index-transaction-export.c:283 resize = ext_reset = {new_reset_id = 0, preserve_data = 0 '\000', unused_padding = "\000\000"} resize_count = ext_count = 6 hdrs = hdrs_count = 6 ext_id = 5 reset_count = 0 hdr_size = 0 reset = 0x0 reset_buf = {data = 0x7fff20dc4ea0, used = 8, priv = {0x7fff20dc4ea0, 0x0, 0x8, 0x0, 0x0}} t = reset_id_count = 0 reset_id = reset_ids = 0x0 #7 mail_index_transaction_export (t=t@entry=0xc6d700, append_ctx=0xc6dcd0) at mail-index-transaction-export.c:409 null4 = "\000\000\000" change_mask = (unknown: 0) ctx = {trans = 0xc6d700, append_ctx = 0xc6dcd0} __FUNCTION__ = "mail_index_transaction_export" #8 0x00007f77b524f32f in mail_index_transaction_commit_real (commit_size_r=0x7fff20dc5000, t=0xc6d700) at mail-index-transaction.c:165 _data_stack_cur_id = 6 ctx = 0xc6dcd0 log_seq2 = 0 log_offset1 = 140733744697296 log = 0xc35bb0 trans_flags = ---Type to continue, or q to quit--- log_seq1 = 24 log_offset2 = 140733193388038 #9 mail_index_transaction_commit_v (t=0xc6d700, result_r=0x7fff20dc4ff0) at mail-index-transaction.c:203 index = 0xc35190 changed = true ret = __FUNCTION__ = "mail_index_transaction_commit_v" #10 0x00007f77b524f78d in mail_index_transaction_commit_full (_t=_t@entry=0x7fff20dc5030, result_r=result_r@entry=0x7fff20dc4ff0) at mail-index-transaction.c:262 t = 0xc6d700 index = 0xc35190 index_undeleted = false #11 0x00007f77b524f82c in mail_index_transaction_commit (t=t@entry=0x7fff20dc5030) at mail-index-transaction.c:236 result = {log_file_seq = 0, log_file_offset = 0, commit_size = 0, ignored_modseq_changes = 0} #12 0x00007f77b51d41ea in mdbox_write_index_header (box=box@entry=0xc345c0, update=update@entry=0x0, trans=0xc6d700, trans@entry=0x0) at mdbox-storage.c:312 mbox = 0xc345c0 new_trans = 0x0 view = 0x0 hdr = 0xc45e00 uid_validity = 1306175995 uid_next = 3038592790 #13 0x00007f77b51d444c in mdbox_mailbox_get_guid (guid_r=0x7fff20dc51f0 "", mbox=0xc345c0) at mdbox-storage.c:391 need_resize = true ret = 0 idx_hdr = hdr = {map_uid_validity = 0, mailbox_guid = '\000' , flags = 0 '\000', unused = "\000\000"} #14 mdbox_mailbox_get_metadata (box=0xc345c0, items=, metadata_r=0x7fff20dc51f0) at mdbox-storage.c:411 items = metadata_r = 0x7fff20dc51f0 box = 0xc345c0 mbox = 0xc345c0 #15 0x00007f77b5226a15 in index_list_get_metadata (box=0xc345c0, items=MAILBOX_METADATA_GUID, metadata_r=0x7fff20dc51f0) at mailbox-list-index-status.c:202 ibox = 0xc34ed0 #16 0x00007f77b5213345 in mailbox_get_metadata (box=0xc345c0, items=items@entry=MAILBOX_METADATA_GUID, metadata_r=metadata_r@entry=0x7fff20dc51f0) at mail-storage.c:1544 __FUNCTION__ = "mailbox_get_metadata" #17 0x00007f77b5227324 in node_lookup_guid (ctx=, guid_r=0x7fff20dc51d8 "", node=0xc30110) at mailbox-list-index-sync.c:25 box = 0xc345c0 vname = str = 0xc11428 ns_sep = metadata = {guid = '\000' , virtual_size = 0, cache_fields = 0x0, precache_fields = (unknown: 0), backend_ns_prefix = 0x0, backend_ns_type = (unknown: 0)} #18 node_add_to_index (seq_r=0x7fff20dc51b0, node=0xc30110, ctx=0xc25bb0) at mailbox-list-index-sync.c:45 _data_stack_cur_id = 5 irec = {name_id = 86, parent_uid = 76, guid = '\000' , uid_validity = 0} seq = 12797376 #19 mailbox_list_index_node_add (seq_r=0x7fff20dc51b0, name=, parent=, ctx=0xc25bb0) at mailbox-list-index-sync.c:87 node = 0xc30110 dup_name = 0xc30140 "Drafts" #20 mailbox_list_index_sync_name (ctx=ctx@entry=0xc25bb0, name=, node_r=node_r@entry=0x7fff20dc5298, created_r=created_r@entry=0x7fff20dc528b) at mailbox-list-index-sync.c:125 path = 0xc11310 empty_path = {0x7f77b52692ff "", 0x0} node = parent = i = 1 seq = 0 ---Type to continue, or q to quit--- __FUNCTION__ = "mailbox_list_index_sync_name" #21 0x00007f77b522794a in mailbox_list_index_sync_list (sync_ctx=0xc25bb0) at mailbox-list-index-sync.c:318 name = _data_stack_cur_id = 4 iter = 0xc31b30 info = 0xc31bb0 flags = (unknown: 0) node = 0xc2ff18 seq = patterns = {0x7f77b52765d3 "*", 0x0} created = false #22 mailbox_list_index_sync (list=list@entry=0xc49360) at mailbox-list-index-sync.c:390 sync_ctx = 0xc25bb0 ret = 0 #23 0x00007f77b522284e in mailbox_list_index_refresh (list=0xc49360) at mailbox-list-index.c:380 ilist = 0xc497f8 view = 0xc275a0 ret = #24 0x00007f77b522672e in index_list_update_mailbox (box=box@entry=0xc4a1a0) at mailbox-list-index-status.c:363 ilist = 0xc497f8 list_sync_ctx = 0xc27270 list_view = 0xc48c20 list_trans = 0x7f77b5213a75 changes = {status = {messages = 256, recent = 0, unseen = 12890576, uidvalidity = 0, uidnext = 65, first_unseen_seq = 0, first_recent_uid = 12886432, last_cached_seq = 0, highest_modseq = 140733744698432, highest_pvt_modseq = 12888328, keywords = 0xc49718, permanent_flags = 3025012879, permanent_keywords = 1, allow_new_keywords = 1, nonpermanent_modseqs = 1, have_guids = 0, have_save_guids = 1, have_only_guid128 = 1}, guid = "\360\261\304\000\000\000\000\000p\247\304\000\000\000\000", seq = 12890576, rec_changed = false, msgs_changed = false, hmodseq_changed = false} ret = __FUNCTION__ = "index_list_update_mailbox" #25 0x00007f77b52269a3 in index_list_sync_deinit (ctx=0x0, status_r=0x7fff20dc5440) at mailbox-list-index-status.c:470 box = 0xc4a1a0 ibox = #26 0x00007f77b5211ef2 in mailbox_sync_deinit (_ctx=_ctx@entry=0x7fff20dc5448, status_r=status_r@entry=0x7fff20dc5440) at mail-storage.c:1691 ctx = box = 0xc4a1a0 errormsg = error = MAIL_ERROR_NONE ret = #27 0x00007f77b5211fa9 in mailbox_sync (box=, flags=) at mail-storage.c:1717 ctx = 0x0 status = {sync_delayed_expunges = 0} #28 0x00000000004022f7 in index_mailbox (what=0xc0f07e "i", max_recent_msgs=0, mailbox=0xc0f076 "INBOX", user=0xc52f00, conn=0xc1bfb0) at master-connection.c:161 box = 0xc4a1a0 status = {messages = 5000, recent = 0, unseen = 3035915435, uidvalidity = 32631, uidnext = 64, first_unseen_seq = 0, first_recent_uid = 12679056, last_cached_seq = 0, highest_modseq = 5000, highest_pvt_modseq = 213, keywords = 0x7f77b4f01ac0 , permanent_flags = 12838464, permanent_keywords = 0, allow_new_keywords = 0, nonpermanent_modseqs = 0, have_guids = 0, have_save_guids = 0, have_only_guid128 = 0} errstr = ret = 0 ns = path = 0xc11048 "/mnt/filestorage01/team.mail.de/m.kliewe/maildir/mailboxes/INBOX/dbox-Mails" error = MAIL_ERROR_NONE sync_flags = #29 master_connection_input_line (line=, conn=0xc1bfb0) at master-connection.c:208 str = max_recent_msgs = 0 ---Type to continue, or q to quit--- ret = args = input = {module = 0x4029ff "mail", service = 0x4029f0 "indexer-worker", username = 0xc0f060 "m.kliewe@team.mail.de", session_id = 0x0, local_ip = {family = 0, u = {ip6 = { __in6_u = {__u6_addr8 = '\000' , __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, ip4 = {s_addr = 0}}}, remote_ip = { family = 0, u = {ip6 = {__in6_u = {__u6_addr8 = '\000' , __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, ip4 = {s_addr = 0}}}, local_port = 0, remote_port = 0, userdb_fields = 0x0, flags_override_add = (unknown: 0), flags_override_remove = (unknown: 0), no_userdb_lookup = 0} service_user = 0xc1f098 user = 0xc52f00 error = 0x7fff20dc5620 "\002" #30 master_connection_input (conn=0xc1bfb0) at master-connection.c:245 _data_stack_cur_id = 3 line = #31 0x00007f77b4f3aa87 in io_loop_call_io (io=0xc1bff0) at ioloop.c:388 ioloop = 0xc17730 t_id = 2 #32 0x00007f77b4f3b817 in io_loop_handler_run (ioloop=ioloop@entry=0xc17730) at ioloop-epoll.c:220 ctx = 0xc1a560 list = 0xc1c040 io = tv = {tv_sec = 0, tv_usec = 0} events_count = msecs = ret = 1 i = 0 call = __FUNCTION__ = "io_loop_handler_run" #33 0x00007f77b4f3a628 in io_loop_run (ioloop=0xc17730) at ioloop.c:412 __FUNCTION__ = "io_loop_run" #34 0x00007f77b4eeb5c3 in master_service_run (service=0xc175c0, callback=callback@entry=0x402090 ) at master-service.c:566 No locals. #35 0x0000000000401f03 in main (argc=1, argv=0xc17390) at indexer-worker.c:78 storage_service_flags = (MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT | MAIL_STORAGE_SERVICE_FLAG_USERDB_LOOKUP | MAIL_STORAGE_SERVICE_FLAG_TEMP_PRIV_DROP | MAIL_STORAGE_SERVICE_FLAG_NO_IDLE_TIMEOUT) c =
Hi,
I just noticed a similar crash (well same assertion at least) on my production server. No idea what the user did, but I know it's a normal client, not some kind of script.
Since I don't know what the user did I can't reproduce the problem, but I figured dropping a note won't hurt.
I'm running dovecot 2.2.11 on Arch Linux with ext4, config and backtraces below.
PS: I'm not subscribed to the list, please make sure to CC me on replies.
Thanks, Florian
###
Apr 14 09:49:29 karif dovecot: imap(user): Panic: file mail-index-transaction-export.c: line 117 (log_append_ext_intro): assertion failed: (intro->ext_id == idx || idx == (uint32_t)-1) Apr 14 09:49:29 karif dovecot: imap(user): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x67450) [0x7f842e6c2450] -> /usr/lib/dovecot/libdovecot.so.0(+0x6752e) [0x7f842e6c252e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f842e67d47e] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xba112) [0x7f842e9e8112] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_export+0x200) [0x7f842e9e85e0] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb979f) [0x7f842e9e779f] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit_full+0x9d) [0x7f842e9e7bfd] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit+0xc) [0x7f842e9e7c9c] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x3e25a) [0x7f842e96c25a] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x3e4bc) [0x7f842e96c4bc] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x90e45) [0x7f842e9bee45] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_get_metadata+0x95) [0x7f842e9ab595] -> /us r/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync_name+0x2a4) [0x7f842e9bf754] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync+0x10a) [0x7f842e9bfd7a] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_refresh+0x9e) [0x7f842e9bac8e] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x90292) [0x7f842e9be292] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x90f9b) [0x7f842e9bef9b] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_get_status+0x31) [0x7f842e9ab4b1] -> dovecot/imap(imap_status_get+0x67) [0x41d5d7] -> dovecot/imap(cmd_status+0x123) [0x413133] -> dovecot/imap(command_exec+0x3c) [0x4170ec] -> dovecot/imap() [0x41614f] -> dovecot/imap() [0x416205] -> dovecot/imap(client_handle_input+0x115) [0x416505] -> dovecot/imap(client_input+0x72) [0x416892] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x27) [0x7f842e6d2527] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0xd7) [0x7f842e6d32b7] -> /usr/lib/dovecot/libdovecot.so.0(io_loo p_run+0x38) [0x7f842e6d20c8] Apr 14 09:49:29 karif dovecot: imap(user): Fatal: master: service(imap): child 20156 killed with signal 6 (core dumped)
backtrace from a core dump below, sadly it doesn't contain much information since the dovecot build I'm running stripped.
#0 0x00007f842e2e8389 in raise () from /usr/lib/libc.so.6 #1 0x00007f842e2e9788 in abort () from /usr/lib/libc.so.6 #2 0x00007f842e6c2446 in ?? () from /usr/lib/dovecot/libdovecot.so.0 #3 0x00007f842e6c252e in ?? () from /usr/lib/dovecot/libdovecot.so.0 #4 0x00007f842e67d47e in i_panic () from /usr/lib/dovecot/libdovecot.so.0 #5 0x00007f842e9e8112 in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #6 0x00007f842e9e85e0 in mail_index_transaction_export () from /usr/lib/dovecot/libdovecot-storage.so.0 #7 0x00007f842e9e779f in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #8 0x00007f842e9e7bfd in mail_index_transaction_commit_full () from /usr/lib/dovecot/libdovecot-storage.so.0 #9 0x00007f842e9e7c9c in mail_index_transaction_commit () from /usr/lib/dovecot/libdovecot-storage.so.0 #10 0x00007f842e96c25a in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #11 0x00007f842e96c4bc in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #12 0x00007f842e9bee45 in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #13 0x00007f842e9ab595 in mailbox_get_metadata () from /usr/lib/dovecot/libdovecot-storage.so.0 #14 0x00007f842e9bf754 in mailbox_list_index_sync_name () from /usr/lib/dovecot/libdovecot-storage.so.0 #15 0x00007f842e9bfd7a in mailbox_list_index_sync () from /usr/lib/dovecot/libdovecot-storage.so.0 #16 0x00007f842e9bac8e in mailbox_list_index_refresh () from /usr/lib/dovecot/libdovecot-storage.so.0 #17 0x00007f842e9be292 in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #18 0x00007f842e9bef9b in ?? () from /usr/lib/dovecot/libdovecot-storage.so.0 #19 0x00007f842e9ab4b1 in mailbox_get_status () from /usr/lib/dovecot/libdovecot-storage.so.0 #20 0x000000000041d5d7 in imap_status_get () #21 0x0000000000413133 in cmd_status () #22 0x00000000004170ec in command_exec () #23 0x000000000041614f in ?? () #24 0x0000000000416205 in ?? () #25 0x0000000000416505 in client_handle_input () #26 0x0000000000416892 in client_input () #27 0x00007f842e6d2527 in io_loop_call_io () from /usr/lib/dovecot/libdovecot.so.0 #28 0x00007f842e6d32b7 in io_loop_handler_run () from /usr/lib/dovecot/libdovecot.so.0 #29 0x00007f842e6d20c8 in io_loop_run () from /usr/lib/dovecot/libdovecot.so.0 #30 0x00007f842e682683 in master_service_run () from /usr/lib/dovecot/libdovecot.so.0 #31 0x000000000040b44f in main ()
config:
# 2.2.11: /etc/dovecot/dovecot.conf # OS: Linux 3.13.8-1-ARCH x86_64 Arch Linux auth_mechanisms = plain login auth_username_format = %Ln login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c %k mail_location = mdbox:~/.mdbox mail_plugins = " zlib notify mail_log" mailbox_list_index = yes 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 ihave namespace inbox { hidden = no inbox = yes list = yes location = mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { auto = subscribe special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox Trash { auto = subscribe special_use = \Trash } prefix = separator = . type = private } passdb { driver = pam } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size sieve = ~/.dovecot.sieve sieve_dir = ~/.sieve sieve_global_dir = /etc/dovecot/sieve/global/ sieve_global_path = /etc/dovecot/sieve/default.sieve zlib_save = gz zlib_save_level = 6 } protocols = imap pop3 sieve lmtp service auth { unix_listener auth-client { group = postfix mode = 0660 user = postfix } user = root } service imap-login { process_limit = 400 process_min_avail = 5 } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } } service managesieve-login { inet_listener sieve-obsolete { port = 2000 } } ssl_cert =
On 1.4.2014, at 21.34, Michael Kliewe mkliewe@gmx.de wrote:
our dovecot processes sometimes crash when we create new folders. The "imap" process and the "indexer worker" process is crashing. We can reproduce this, we have a java program with multiple threads, and sometimes 2 threads try to create the same folder for the same user, and if both collide, dovecot processes crash.
We don't see this happening in the real world if "normal" imap clients are connected, but our special java program trying to create folders in parallel is producing these crashes. .. Apr 1 19:58:28 dovecot01 dovecot: imap(user@domain.de): Panic: file mail-index-transaction-export.c: line 117 (log_append_ext_intro): assertion failed: (intro->ext_id == idx || idx == (uint32_t)-1)
participants (3)
-
Florian Pritz
-
Michael Kliewe
-
Timo Sirainen