2.2.15 Panic in mbox_sync_read_next_mail()
It might not be a fault in dovecot, as the user is accessing the folder locally with alpine while also running imap-sessions. However it would have been nice with a more graceful action than panic?
The panic is preceeded by Error: Next message unexpectedly corrupted in mbox file PATH
Panic: file mbox-sync.c: line 152 (mbox_sync_read_next_mail): assertion failed: (sync_ctx->input->v_offset != mail_ctx->mail.from_offset || sync_ctx->input->eof)
At #7 in the enclosed backtrace the actual values are sync_ctx->input->v_offset = 564 mail_ctx->mail.from_offset = 564 sync_ctx->input->eof = 0
Some will recommend convertion to maildir, but with 25 years history, thousands of active users and dozens terrabytes of mboxes, we are not even considering it.
hmk
GNU gdb 6.8 Copyright (C) 2008 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 "i386-pc-solaris2.10"... Reading symbols from /datapool/local/dovecot-2.2.15/lib/dovecot/libdovecot-storage.so.0...done. Loaded symbols for /local/dovecot-2.2.15/lib/dovecot/libdovecot-storage.so.0 Reading symbols from /datapool/local/dovecot-2.2.15/lib/dovecot/libdovecot.so.0...done. Loaded symbols for /local/dovecot-2.2.15/lib/dovecot/libdovecot.so.0 Reading symbols from /datapool/local/program/lib/libssl.so.1.0.0...done. Loaded symbols for /local/program/lib/libssl.so.1.0.0 Reading symbols from /datapool/local/program/lib/libcrypto.so.1.0.0...done. Loaded symbols for /local/program/lib/libcrypto.so.1.0.0 Reading symbols from /datapool/local/program/lib/libz.so...done. Loaded symbols for /local/program/lib/libz.so Reading symbols from /lib/libm.so.2...done. Loaded symbols for /lib/libm.so.2 Reading symbols from /datapool/local/program/lib/libiconv.so.2...done. Loaded symbols for /local/program/lib/libiconv.so.2 Reading symbols from /lib/librt.so.1...done. Loaded symbols for /lib/librt.so.1 Reading symbols from /lib/libnsl.so.1...done. Loaded symbols for /lib/libnsl.so.1 Reading symbols from /lib/libsocket.so.1...done. Loaded symbols for /lib/libsocket.so.1 Reading symbols from /lib/libsendfile.so.1...done. Loaded symbols for /lib/libsendfile.so.1 Reading symbols from /lib/libc.so.1...done. Loaded symbols for /lib/libc.so.1 Reading symbols from /lib/libdl.so.1...done. Loaded symbols for /lib/libdl.so.1 Reading symbols from /usr/lib/libz.so...done. Loaded symbols for /usr/lib/libz.so Reading symbols from /lib/libaio.so.1...done. Loaded symbols for /lib/libaio.so.1 Reading symbols from /lib/libmd.so.1...done. Loaded symbols for /lib/libmd.so.1 Reading symbols from /lib/ld.so.1...done. Loaded symbols for /lib/ld.so.1 Core was generated by `dovecot/imap imap-postlogin'. Program terminated with signal 6, Aborted. [New process 86892 ] #0 0xfe80c8e5 in _lwp_kill () from /lib/libc.so.1 (gdb) #0 0xfe80c8e5 in _lwp_kill () from /lib/libc.so.1 No symbol table info available. #1 0xfe807765 in thr_kill () from /lib/libc.so.1 No symbol table info available. #2 0xfe7b376f in raise () from /lib/libc.so.1 No symbol table info available. #3 0xfe7929e1 in abort () from /lib/libc.so.1 No symbol table info available. #4 0xfeda1c82 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at failures.c:152 backtrace = 0x8093260 "0xfeda2b9f -> 0xfeda1e9b -> 0xfee9f57a -> 0xfeea207c -> 0xfeea37e9 -> 0xfeea4363 -> 0xfeea45cd -> 0xfeea477d -> 0xfeecb356 -> 0x8074b45 -> 0x805eeda -> 0x805f463 -> 0x806aad1 -> 0x8069a41 -> 0x8069d26"... #5 0xfeda2b9f in i_internal_fatal_handler (ctx=0x80474e0, format=0xfef4c588 "file %s: line %d (%s): assertion failed: (%s)", args=0x8047504 "°Æôþ\230") at failures.c:152 status = 0 #6 0xfeda1e9b in i_panic (format=0xfef4c588 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:152 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0, timestamp_usecs = 0} args = 0x8047504 "°Æôþ\230" #7 0xfee9f57a in mbox_sync_read_next_mail (sync_ctx=0x8047794, mail_ctx=0x804760c) at ../../../../src/lib/array.h:158 __FUNCTION__ = "mbox_sync_read_next_mail" #8 0xfeea207c in mbox_sync_loop (sync_ctx=0x8047794, mail_ctx=0x804760c, partial=false) at ../../../../src/lib/array.h:158 rec = (const struct mail_index_record *) 0x0 uid = 0 messages_count = 66 offset = 564 ret = 1 expunged = false skipped_mails = true uids_broken = false #9 0xfeea37e9 in mbox_sync_do (sync_ctx=0x8047794, flags=0) at ../../../../src/lib/array.h:158 mbox_hdr = (struct mbox_index_header *) 0x80b4a20 mail_ctx = {sync_ctx = 0x8047794, mail = {uid = 0, idx_seq = 0, keywords = {arr = { buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}, flags = 32 ' ', uid_broken = 0, expunged = 0, pseudo = 0, status_broken = 0, xstatus_broken = 0, from_offset = 564, body_size = 0, offset = 564, space = 0}, seq = 2, hdr_offset = 564, body_offset = 564, header_first_change = 4294967295, header_last_change = 0, header = 0x809c758, hdr_md5_sum = "Ô\035\214Ù\217\000²\004é\200\t\230ìøB~", content_length = 18446744073709551615, hdr_pos = {4294967295, 4294967295, 4294967295, 4294967295, 4294967295}, parsed_uid = 0, last_uid_updated_value = 0, last_uid_value_start_pos = 0, have_eoh = 0, need_rewrite = 0, seen_imapbase = 0, updated = 0, recent = 0, dirty = 0, imapbase_rewrite = 0, imapbase_updated = 0} st = (const struct stat *) 0x80c0060 i = 0 ret = 52 partial = 1 #10 0xfeea4363 in mbox_sync_int (mbox=0x80b4868, flags=0, lock_id=0x8047988) at ../../../../src/lib/array.h:158 index_sync_ctx = (struct mail_index_sync_ctx *) 0x80b62e0 sync_view = (struct mail_index_view *) 0x80b6320 trans = (struct mail_index_transaction *) 0x80c5890 sync_ctx = {mbox = 0x80b4868, flags = 0, input = 0x80c0180, file_input = 0x80c0040, write_fd = 12, orig_mtime = 1414582020, orig_atime = 1414582021, orig_size = 3843471, last_stat = { st_dev = 47513605, st_pad1 = {0, 0, 0}, st_ino = 17869, st_mode = 33152, st_nlink = 1, st_uid = 22671, st_gid = 4601, st_rdev = 4294967295, st_pad2 = {0, 0}, st_size = 3843471, st_atim = {tv_sec = 1414582021, tv_nsec = 353242309}, st_mtim = {tv_sec = 1414582020, tv_nsec = 0}, st_ctim = {tv_sec = 1414582021, tv_nsec = 352990278}, st_blksize = 131072, st_blocks = 7693, st_fstype = "zfs", '\0' <repeats 12 times>, st_pad4 = {0, 0, 0, 0, 0, 0, 0, 0}}, index_sync_ctx = 0x80b62e0, sync_view = 0x80b6320, t = 0x80c5890, reset_hdr = { major_version = 0 '\0', minor_version = 0 '\0', base_header_size = 0, header_size = 0, record_size = 0, compat_flags = 0 '\0', unused = "\000\000", indexid = 0, flags = 0, uid_validity = 0, next_uid = 0, messages_count = 0, unused_old_recent_messages_count = 0, seen_messages_count = 0, deleted_messages_count = 0, first_recent_uid = 0, first_unseen_uid_lowwater = 0, first_deleted_uid_lowwater = 0, log_file_seq = 0, log_file_tail_offset = 0, log_file_head_offset = 0, unused_old_sync_size = 0, unused_old_sync_stamp = 0, day_stamp = 0, day_first_uid = {0, 0, 0, 0, 0, 0, 0, 0}}, hdr = 0x80c5b68, header = 0x809c758, from_line = 0x809c6b8, base_uid_validity = 1353318516, base_uid_last = 144140, base_uid_last_offset = 250, mails = {arr = {buffer = 0x809c640, element_size = 52}, v = 0x809c640, v_modifiable = 0x809c640}, sync_changes = 0x80ab998, mail_keyword_pool = 0x80bf220, saved_keywords_pool = 0x80bcbe0, prev_msg_uid = 0, next_uid = 144141, idx_next_uid = 144141, seq = 2, idx_seq = 1, need_space_seq = 0, last_nonrecent_uid = 0, expunged_space = 0, space_diff = 0, dest_first_mail = 0, first_mail_crlf_expunged = 0, keep_recent = 0, readonly = 0, delay_writes = 1, renumber_uids = 0, moved_offsets = 0, ext_modified = 0, index_reset = 0, errors = 0} sync_flags = MAIL_INDEX_SYNC_FLAG_DROP_RECENT ret = 1 changed = 1 delay_writes = true readonly = false __FUNCTION__ = "mbox_sync_int" #11 0xfeea45cd in mbox_sync (mbox=0x80b4868, flags=0) at ../../../../src/lib/array.h:158 lock_id = 47 ret = 134957840 __FUNCTION__ = "mbox_sync" #12 0xfeea477d in mbox_storage_sync_init (box=0x80b4868, flags=0) at ../../../../src/lib/array.h:158 mbox = (struct mbox_mailbox *) 0x80b4868 mbox_sync_flags = 0 ret = 0 #13 0xfeecb356 in mailbox_sync_init (box=0x80b4868, flags=0) at ../../src/lib/array.h:197 _data_stack_cur_id = 4 ctx = (struct mailbox_sync_context *) 0x0 #14 0x08074b45 in imap_sync_init (client=0x80b1850, box=0x80b4868, imap_flags=0, flags=0) at ../../src/lib/array.h:158 ctx = (struct imap_sync_context *) 0x80b61b0 __FUNCTION__ = "imap_sync_init" #15 0x0805eeda in idle_sync_now (box=0x80b4868, ctx=0x80b20e0) at cmd-idle.c:74 __FUNCTION__ = "idle_sync_now" #16 0x0805f463 in cmd_idle (cmd=0x80b2058) at cmd-idle.c:74 client = (struct client *) 0x80b1850 ctx = (struct cmd_idle_context *) 0x80b20e0 #17 0x0806aad1 in command_exec (cmd=0x80b2058) at imap-commands.c:101 hook = (const struct command_hook *) 0x809c078 ret = 8 #18 0x08069a41 in client_command_input (cmd=0x80b2058) at imap-client.c:130 client = (struct client *) 0x80b1850 command = (struct command *) 0x3 __FUNCTION__ = "client_command_input" #19 0x08069d26 in client_command_input (cmd=0x80b2058) at imap-client.c:130 client = (struct client *) 0x80b1850 command = (struct command *) 0x809d3cc __FUNCTION__ = "client_command_input" #20 0x08069e29 in client_handle_next_command (client=0x80b1850, remove_io_r=0x8047b9d) at imap-client.c:130 No locals. #21 0x08069ec6 in client_handle_input (client=0x80b1850) at imap-client.c:130 _data_stack_cur_id = 3 ret = 10 remove_io = false handled_commands = false __FUNCTION__ = "client_handle_input" #22 0x0806a04f in client_input (client=0x80b1850) at imap-client.c:130 cmd = (struct client_command_context *) 0x80aaa44 output = (struct ostream *) 0x80abea8 bytes = 10 __FUNCTION__ = "client_input" #23 0xfedbb235 in io_loop_call_io (io=0x80abf10) at ioloop.c:28 ioloop = (struct ioloop *) 0x809bfc0 t_id = 2 __FUNCTION__ = "io_loop_call_io" #24 0xfedbc994 in io_loop_handler_run_internal (ioloop=0x809bfc0) at ioloop-poll.c:96 ctx = (struct ioloop_handler_context *) 0x809cab0 pollfd = (struct pollfd *) 0x809e148 tv = {tv_sec = 1799, tv_usec = 999001} io = (struct io_file *) 0x80abf10 msecs = 1800000 ret = 0 call = true #25 0xfedbb3ce in io_loop_handler_run (ioloop=0x809bfc0) at ioloop.c:28 No locals. #26 0xfedbb325 in io_loop_run (ioloop=0x809bfc0) at ioloop.c:28 __FUNCTION__ = "io_loop_run" #27 0xfed41dc1 in master_service_run (service=0x809bf08, callback=0x807724a <client_connected>) at master-service.c:75 No locals. #28 0x080775e7 in main (argc=2, argv=0x809bd18) at main.c:72 set_roots = {0x8093080, 0x0} login_set = {auth_socket_path = 0x8093188 " 1\t\b", postlogin_socket_path = 0x80931c0 "", postlogin_timeout_secs = 60, callback = 0x8076fbe <login_client_connected>, failure_callback = 0x80771cd <login_client_failed>, request_auth_token = 1} service_flags = MASTER_SERVICE_FLAG_KEEP_CONFIG_OPEN storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT username = 0x0 c = -1
Interesting. We are expiring the same problem here. But our user is currently traveling in the world and uses our roundcube to access its emails:
The panic is preceeded by Error: Next message unexpectedly corrupted in mbox file PATH
Panic: file mbox-sync.c: line 152 (mbox_sync_read_next_mail): assertion failed: (sync_ctx->input->v_offset != mail_ctx->mail.from_offset || sync_ctx->input->eof)
At #7 in the enclosed backtrace the actual values are sync_ctx->input->v_offset = 564 mail_ctx->mail.from_offset = 564 sync_ctx->input->eof = 0
I can not attach a gdb output because until yet i could not catch a core dump.
Here the last lines from the logfile:
Oct 29 07:46:34 SERVER dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: Namespace : type=private, prefix=Mail/, sep=/, inbox=no, hidden=yes, list=no, subscriptions=yes location=mbox:~/Mail/:INBOX=/var/mail/USERNAME:INDEX=/usr/SERVER/vault2/dovecot/indexes/USERNAME
Oct 29 07:46:34 SERVER dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: fs: root=/home/USERNAME/Mail, index=/usr/SERVER/vault2/dovecot/indexes/USERNAME, indexpvt=, control=, inbox=/var/mail/USERNAME, alt=
Oct 29 07:46:34 SERVER dovecot: [ID 583609 mail.info] imap(USERNAME): Disconnected: Logged out in=374 out=60850
Oct 29 07:46:35 SERVER dovecot: [ID 583609 mail.error] imap(USERNAME): Error: Next message unexpectedly corrupted in mbox file /home/USERNAME/Mail/MBOXFILE at 38055772
Oct 29 07:46:35 SERVER dovecot: [ID 583609 mail.crit] imap(USERNAME): Panic: file mbox-sync.c: line 152 (mbox_sync_read_next_mail): assertion failed: (sync_ctx->input->v_offset != mail_ctx->mail.from_offset || sync_ctx->input->eof)
Oct 29 07:46:35 SERVER dovecot: [ID 583609 mail.error] imap(USERNAME): Error: Raw backtrace: 0xffffffff7ed89f64 -> 0xffffffff7ed88f10 -> 0xffffffff7ef77a14 -> 0xffffffff7ef78a1c -> 0xffffffff7ef78e98 -> 0xffffffff7ef962d0 -> 0xffffffff7ef96418 -> 0xffffffff7efc2380 -> 0xffffffff7ef9777c -> 0x100021554 -> 0x100013e8c -> 0x100019044 -> 0x100017b18 -> 0x100017ad8 -> 0x100017f3c -> 0x100018188 -> 0xffffffff7ed9c8a4 -> 0xffffffff7ed9d5a0 -> 0xffffffff7ed9c93c -> 0xffffffff7ed9ca0c -> 0xffffffff7ed3c314 -> 0x100024908 -> 0x10000a74c
Oct 29 07:46:35 SERVER dovecot: [ID 583609 mail.crit] imap(USERNAME): Fatal: master: service(imap): child 19457 killed with signal 6 (core not dumped - set service imap { drop_priv_before_exec=yes })
I have set the drop_priv_before_exec to yes, i'm just waiting for the user to connect again ;-)
Our System is a Solaris 10 and we are also using mbox for more or less the same reason as hmk.
As soon as i can catch a coredump i will send a gdb output.
Since all other users do not have such a problem i'm wondering what the reason for this could be? corrupt mbox file?
Best Regards Matthias
-- Matthias Egger ETH Zurich Department of Information Technology maegger@ee.ethz.ch and Electrical Engineering IT Support Group (ISG.EE), ETL/F/24.1 Phone +41 (0)44 632 03 90 Physikstrasse 3, CH-8092 Zurich Fax +41 (0)44 632 11 95
On 10/29/2014 02:50 PM, Matthias Egger wrote:
As soon as i can catch a coredump i will send a gdb output.
Okay, here is the gdb ouput i could catch and some more information about the system.
System Infos: SunOS HOSTNAME 5.10 Generic_150400-10 sun4u sparc SUNW,Sun-Fire-V440
Logfile Entries: Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.info] imap-login: Login: user=<USERNAME>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=15565, TLS, session=<B6os2aMGoACBhDSe>
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: Effective uid=3224, gid=320, home=/home/USERNAME
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mbox:~/Mail/:INBOX=/var/mail/USERNAME:INDEX=/usr/HOSTNAME/vault2/dovecot/indexes/USERNAME
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: fs: root=/home/USERNAME/Mail, index=/usr/HOSTNAME/vault2/dovecot/indexes/USERNAME, indexpvt=, control=, inbox=/var/mail/USERNAME, alt=
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: Namespace : type=private, prefix=Mail/, sep=/, inbox=no, hidden=yes, list=no, subscriptions=yes location=mbox:~/Mail/:INBOX=/var/mail/USERNAME:INDEX=/usr/HOSTNAME/vault2/dovecot/indexes/USERNAME
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.debug] imap(USERNAME): Debug: fs: root=/home/USERNAME/Mail, index=/usr/HOSTNAME/vault2/dovecot/indexes/USERNAME, indexpvt=, control=, inbox=/var/mail/USERNAME, alt=
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.error] imap(USERNAME): Error: Next message unexpectedly corrupted in mbox file /home/USERNAME/Mail/review at 79036384
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.crit] imap(USERNAME): Panic: file mbox-sync.c: line 152 (mbox_sync_read_next_mail): assertion failed: (sync_ctx->input->v_offset != mail_ctx->mail.from_offset || sync_ctx->input->eof)
Oct 30 14:27:56 HOSTNAME dovecot: [ID 583609 mail.error] imap(USERNAME): Error: Raw backtrace: 0xffffffff7ed89f64 -> 0xffffffff7ed88f10 -> 0xffffffff7ef77a14 -> 0xffffffff7ef78a1c -> 0xffffffff7ef70720 -> 0xffffffff7c10289c -> 0xffffffff7ef96e60 -> 0xffffffff7ef8dd6c -> 0xffffffff7c102758 -> 0xffffffff7ef97130 -> 0xffffffff7ef97250 -> 0x10000c8c8 -> 0x10000ce24 -> 0x100019044 -> 0x100017b18 -> 0x100017ad8 -> 0x100017f3c -> 0x100018188 -> 0xffffffff7ed9c8a4 -> 0xffffffff7ed9d5a0 -> 0xffffffff7ed9c93c -> 0xffffffff7ed9ca0c -> 0xffffffff7ed3c314 -> 0x100024908 -> 0x10000a74c
Oct 30 14:27:57 HOSTNAME dovecot: [ID 583609 mail.crit] imap(USERNAME): Fatal: master: service(imap): child 15565 killed with signal 6 (core dumped)
GDB Output: GNU gdb (GDB) 7.8.1 Copyright (C) 2014 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 "sparc-sun-solaris2.10". Type "show configuration" for configuration details. For bug reporting instructions, please see: <http://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/pack/dovecot-2.2.15-me/sun4u-sun-solaris2.10/libexec/dovecot/imap...done. [New LWP 1] [Thread debugging using libthread_db enabled] [New Thread 1 (LWP 1)] Core was generated by `dovecot/imap'. Program terminated with signal SIGABRT, Aborted. #0 0xffffffff7cddcb68 in _lwp_kill () from /lib/64/libc.so.1 (gdb) bt full #0 0xffffffff7cddcb68 in _lwp_kill () from /lib/64/libc.so.1 No symbol table info available. #1 0xffffffff7cd74444 in raise () from /lib/64/libc.so.1 No symbol table info available. #2 0xffffffff7cd4c1c8 in abort () from /lib/64/libc.so.1 No symbol table info available. #3 0xffffffff7ed88d7c in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at failures.c:202 backtrace = 0x100133db0 "0xffffffff7ed89f64 -> 0xffffffff7ed88f10 -> 0xffffffff7ef77a14 -> 0xffffffff7ef78a1c -> 0xffffffff7ef70720 -> 0xffffffff7c10289c -> 0xffffffff7ef96e60 -> 0xffffffff7ef8dd6c -> 0xffffffff7c102758 -> 0x"... #4 0xffffffff7ed89f6c in i_internal_fatal_handler (ctx=0xffffffff7fffe2e0, format=0xffffffff7effba48 "file %s: line %d (%s): assertion failed: (%s)", args=0x0) at failures.c:666 status = 0 #5 0xffffffff7ed88f18 in i_panic (format=0xffffffff7effba48 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:276 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0, timestamp_usecs = 0} #6 0xffffffff7ef77a1c in mbox_sync_do (sync_ctx=0xffffffff7fffe760, flags=(MBOX_SYNC_FORCE_SYNC | MBOX_SYNC_READONLY | unknown: 2147477248)) at mbox-sync.c:1506 seq = 1611168 view = 0xffffffff7eeddcf8 st = 0x0 first_recent_uid = 0 seq2 = 1 mbox_hdr = 0x1 mail_ctx = {sync_ctx = 0xffffffff7fffe760, mail = {uid = 0, idx_seq = 0, keywords = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}, flags = 32 ' ', uid_broken = 0, expunged = 0, pseudo = 0, status_broken = 0, xstatus_broken = 0, from_offset = 558, body_size = 0, offset = 558, space = 0}, seq = 2, hdr_offset = 558, body_offset = 558, header_first_change = 18446744073709551615, header_last_change = 0, header = 0x100140230, hdr_md5_sum = "\324\035\214\331\217\000\262\004\351\200\t\230\354\370B~", content_length = 18446744073709551615, hdr_pos = {18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615}, parsed_uid = 0, last_uid_updated_value = 0, last_uid_value_start_pos = 0, have_eoh = 0, need_rewrite = 0, seen_imapbase = 0, updated = 0, recent = 0, dirty = 0, imapbase_rewrite = 0, imapbase_updated = 0} st = 0x1001895c8 i = 0 ret = 1389811195 partial = 1389811195 #7 0xffffffff7ef78a24 in mbox_sync (mbox=0x100163a50, flags=(unknown: 0)) at mbox-sync.c:1947 sync_ctx = {mbox = 0x100163a50, flags = (unknown: 0), input = 0x100189750, file_input = 0x1001895a0, write_fd = 16, orig_mtime = 1414623452, orig_atime = 1414675298, orig_size = 80880344, last_stat = { st_dev = 1657857376531, st_ino = 128607, st_mode = 33152, st_nlink = 1, st_uid = 3224, st_gid = 320, st_rdev = 0, st_size = 80880344, st_atim = {tv_sec = 1414675298, tv_nsec = 859380000}, st_mtim = { tv_sec = 1414623452, tv_nsec = 0}, st_ctim = {tv_sec = 1414623453, tv_nsec = 933899000}, st_blksize = 8192, st_blocks = 158080, st_fstype = "nfs", '\000' <repeats 12 times>}, index_sync_ctx = 0x1001855d0, sync_view = 0x100185640, t = 0x100185c40, reset_hdr = {major_version = 0 '\000', minor_version = 0 '\000', base_header_size = 0, header_size = 0, record_size = 0, compat_flags = 0 '\000', unused = "\000\000", indexid = 0, flags = 0, uid_validity = 0, next_uid = 0, messages_count = 0, unused_old_recent_messages_count = 0, seen_messages_count = 0, deleted_messages_count = 0, first_recent_uid = 0, first_unseen_uid_lowwater = 0, first_deleted_uid_lowwater = 0, log_file_seq = 0, log_file_tail_offset = 0, log_file_head_offset = 0, unused_old_sync_size = 0, unused_old_sync_stamp = 0, day_stamp = 0, day_first_uid = {0, 0, 0, 0, 0, 0, 0, 0}}, hdr = 0x100167a90, header = 0x100140230, from_line = 0x1001401e0, base_uid_validity = 1389811195, base_uid_last = 770, base_uid_last_offset = 264, mails = {arr = {buffer = 0x100140280, element_size = 64}, v = 0x100140280, v_modifiable = 0x100140280}, sync_changes = 0x100161130, mail_keyword_pool = 0x1001870d0, saved_keywords_pool = 0x1001872e0, prev_msg_uid = 0, next_uid = 771, idx_next_uid = 744, seq = 2, idx_seq = 1, need_space_seq = 0, last_nonrecent_uid = 0, expunged_space = 0, space_diff = 0, dest_first_mail = 0, first_mail_crlf_expunged = 0, keep_recent = 1, readonly = 0, delay_writes = 1, renumber_uids = 0, moved_offsets = 0, ext_modified = 0, index_reset = 0, errors = 0} sync_flags = (MAIL_INDEX_SYNC_FLAG_DROP_RECENT | MAIL_INDEX_SYNC_FLAG_AVOID_FLAG_UPDATES | MAIL_INDEX_SYNC_FLAG_DELETING_INDEX | MAIL_INDEX_SYNC_FLAG_TRY_DELETING_INDEX | unknown: 640) index_sync_ctx = 0x1001855d0 sync_view = 0x100185640 ret = 1259088 trans = 0x100185c40 changed = 1 delay_writes = true readonly = false lock_id = 3 ret = 1 __FUNCTION__ = "mbox_sync" #8 0xffffffff7ef70728 in mbox_save_begin (_ctx=0x100178880, input=0x100184bc0) at mbox-save.c:317 mbox = 0x100163a50 storage = 0x1001566e0 empty = false ret = 1 mdata = 0x100178890 t = 0x100171ab0 save_flags = 1456720 offset = 18446744069414584321 __FUNCTION__ = "mbox_save_begin" #9 0xffffffff7c1028a4 in notify_save_begin (ctx=0x100178880, input=0x100184bc0) at notify-storage.c:132 lt = 0x10013bf10 lbox = 0x1001640c0 #10 0xffffffff7ef96e68 in mailbox_save_begin (ctx=0xffffffff7fffee30, input=0x100184bc0) at mail-storage.c:2087 _data_stack_cur_id = 5 box = 0x100163a50 ret = 1456720 #11 0xffffffff7ef8dd74 in mail_storage_copy (ctx=0x100178880, mail=0x1001740a0) at mail-copy.c:76 input = 0x100184bc0 #12 0xffffffff7c102760 in notify_copy (ctx=0x100178880, mail=0x1001740a0) at notify-storage.c:108 lt = 0xffffffffffffffff lbox = 0x1001640c0 ret = 1458368 #13 0xffffffff7ef97138 in mailbox_copy (_ctx=0xffffffff7ffff0e0, mail=0x1001740a0) at mail-storage.c:2212 _data_stack_cur_id = 4 ctx = 0x100178880 t = 0x100171ab0 keywords = 0x0 pvt_flags = 0 backend_mail = 0x1001740a0 ret = 2147479776 __FUNCTION__ = "mailbox_copy" #14 0xffffffff7ef97258 in mailbox_move (_ctx=0xffffffff7ffff0e0, mail=0x1001740a0) at mail-storage.c:2234 ctx = 0x100178880 #15 0x000000010000c8d0 in cmd_copy_full (cmd=0x100157ab0, move=true) at cmd-copy.c:67 search_ctx = 0x100173f30 src_trans = 0x100172cf0 srcset_ctx = {str = 0x100133c00, first_uid = 0, last_uid = 4294967295} ret = 1 save_ctx = 0x0 mail = 0x1001740a0 copy_count = 1 src_uidset = 0x100133c00 move = true search_args = 0x1 client = 0x1001572a0 dest_storage = 0x1 destbox = 0x100163a50 t = 0x100171ab0 src_trans = 0x84 search_args = 0x100162a40 messageset = 0x1001514e0 "237752" mailbox = 0x1001514e8 "review" src_uidset = 0x81 <error: Cannot access memory at address 0x81> sync_flags = (unknown: 0) imap_flags = (unknown: 0) changes = {pool = 0x3132392e3133322e, uid_validity = 892481073, saved_uids = {arr = {buffer = 0x81, element_size = 18446744071544102136}, v = 0x81, v_modifiable = 0x81}, ignored_modseq_changes = 1, changed = false, no_read_perm = 21} copy_count = 8 msg = 0x100171ab0 ret = 1 __FUNCTION__ = "cmd_copy_full" #16 0x000000010000ce2c in cmd_move (cmd=0x100157ab0) at cmd-copy.c:211 No locals. #17 0x000000010001904c in command_exec (cmd=0x100157ab0) at imap-commands.c:158 hook = 0x10013e700 ret = 63 #18 0x0000000100017b20 in client_command_input (cmd=0x100157ab0) at imap-client.c:782 client = 0x1001572a0 command = 0x0 __FUNCTION__ = "client_command_input" #19 0x0000000100017ae0 in client_command_input (cmd=0x100157ab0) at imap-client.c:843 client = 0x1001572a0 command = 0x0 __FUNCTION__ = "client_command_input" #20 0x0000000100017f44 in client_handle_input (client=0x1001572a0) at imap-client.c:880 _data_stack_cur_id = 3 ret = false remove_io = false handled_commands = false __FUNCTION__ = "client_handle_input" #21 0x0000000100018190 in client_input (client=0x1001572a0) at imap-client.c:935 cmd = 0xf1942 output = 0x100151250 bytes = 30 __FUNCTION__ = "client_input" #22 0xffffffff7ed9c8ac in io_loop_call_io (io=0x100143b60) at ioloop.c:498 ioloop = 0x10013cd80 t_id = 2 __FUNCTION__ = "io_loop_call_io" #23 0xffffffff7ed9d5a8 in io_loop_handler_run_internal (ioloop=0x10013cd80) at ioloop-poll.c:211 ctx = 0x10013ce60 pollfd = 0x100142470 tv = {tv_sec = 4, tv_usec = 990294} io = 0x100143b60 ret = 0 call = false #24 0xffffffff7ed9c944 in io_loop_handler_run (ioloop=0x10013cd80) at ioloop.c:545 No locals. #25 0xffffffff7ed9ca14 in io_loop_run (ioloop=0x10013cd80) at ioloop.c:523 __FUNCTION__ = "io_loop_run" #26 0xffffffff7ed3c31c in master_service_run (service=0x10013cc50, callback=0x100024318 <client_connected>) at master-service.c:566 No locals. #27 0x0000000100024910 in main (argc=1, argv=0xffffffff7ffffca8) at main.c:412 set_roots = {0x10002d5e0 <imap_setting_parser_info>, 0x0} login_set = {auth_socket_path = 0x100133920 "", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x100024054 <login_client_connected>, failure_callback = 0x1000242bc <login_client_failed>, request_auth_token = 1} service_flags = (MASTER_SERVICE_FLAG_KEEP_CONFIG_OPEN | MASTER_SERVICE_FLAG_NO_CONFIG_SETTINGS | MASTER_SERVICE_FLAG_UPDATE_PROCTITLE | MASTER_SERVICE_FLAG_USE_SSL_SETTINGS | unknown: 147456) storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT username = 0x133400 <error: Cannot access memory at address 0x133400> c = 1297488
Best regards Matthias
Matthias Egger ETH Zurich Department of Information Technology maegger@ee.ethz.ch and Electrical Engineering IT Support Group (ISG.EE), ETL/F/24.1 Phone +41 (0)44 632 03 90 Physikstrasse 3, CH-8092 Zurich Fax +41 (0)44 632 11 95
On 30/10/14 15:44, Matthias Egger wrote:
On 10/29/2014 02:50 PM, Matthias Egger wrote:
As soon as i can catch a coredump i will send a gdb output. Okay, here is the gdb ouput i could catch and some more information about the system.
System Infos: SunOS HOSTNAME 5.10 Generic_150400-10 sun4u sparc SUNW,Sun-Fire-V440
We are experiencing the same issues on CentOS 5: Linux 2.6.18-371.12.1.el5 x86_64
At first, we were reindexing all users with this issue (doveadm index), now we are just forcing mailbox resync (doveadm force-mailbox-resync), however it is not fixing it :(
We still don't have the pattern, when does this occur (multiple IMAP sessions?, IMAP/POP)...
We might revert to 2.2.13, where such problems were way less frequent.
cheers, Jernej
Has someone of you just found any kind of solution to this problem?
We first had only one user with this problem. But now there are two more users expecting the same problems. And as Jernej said, doveadm "index" and "force-resync" do not solve the problem at all. After a few hours these users have the same kind of errors and crashes.
We have now reverted back to 2.2.13 but that could not be a permanent solution.
Timo Sirainen, have you maybe given a look to this or any hint?
Best regards Matthias
Matthias Egger ETH Zurich Department of Information Technology maegger@ee.ethz.ch and Electrical Engineering IT Support Group (ISG.EE), ETL/F/24.1 Phone +41 (0)44 632 03 90 Physikstrasse 3, CH-8092 Zurich Fax +41 (0)44 632 11 95
On 11/04/2014 01:38 PM, Matthias Egger wrote:
Has someone of you just found any kind of solution to this problem?
Could the people experiencing this please send at least a) output of doveconf -n b) anonymized mbox content for an affected mbox ( http://www.dovecot.org/tools/mbox-anonymize.pl ). Other details can not hurt either.
br, Teemu Huovila
On Tue, Nov 04, 2014 at 12:38:02PM +0100, Matthias Egger wrote:
Has someone of you just found any kind of solution to this problem?
We have been running some days with patches 31262a892ba7 and 80ed82a93c1a from http://hg.dovecot.org/dovecot-2.2/
They are working fine, handling the previously paniced situations smoothly. Thanks again to the folks at dovecot.org!
hmk
Hello Hans
On 11/23/2014 05:57 PM, Hans Morten Kind wrote:
On Tue, Nov 04, 2014 at 12:38:02PM +0100, Matthias Egger wrote:
Has someone of you just found any kind of solution to this problem?
We have been running some days with patches 31262a892ba7 and 80ed82a93c1a from http://hg.dovecot.org/dovecot-2.2/
They are working fine, handling the previously paniced situations smoothly. Thanks again to the folks at dovecot.org!
Thank you for sharing this. I will give today or tomorrow a look at these patches.
Matthias
-- Matthias Egger ETH Zurich Department of Information Technology maegger@ee.ethz.ch and Electrical Engineering IT Support Group (ISG.EE), ETL/F/24.1 Phone +41 (0)44 632 03 90 Physikstrasse 3, CH-8092 Zurich Fax +41 (0)44 632 11 95
On 26/11/14 10:09, Matthias Egger wrote:
Hello Hans
On 11/23/2014 05:57 PM, Hans Morten Kind wrote:
On Tue, Nov 04, 2014 at 12:38:02PM +0100, Matthias Egger wrote:
Has someone of you just found any kind of solution to this problem?
We have been running some days with patches 31262a892ba7 and 80ed82a93c1a from http://hg.dovecot.org/dovecot-2.2/
They are working fine, handling the previously paniced situations smoothly. Thanks again to the folks at dovecot.org!
Thank you for sharing this. I will give today or tomorrow a look at these patches.
At least at our side, these patches have fixed a large number of segfaults opening mbox files.
Thank you Timo and dovecot team!!!
cheers, Jernej
participants (5)
-
Hans Morten Kind
-
Hans Morten Kind
-
Jernej Porenta
-
Matthias Egger
-
Teemu Huovila