[Dovecot] dovecot 1.1.rc3 assertion failed at index_mailbox_set_recent_uid while deleting message with thunderbird.
To some users happens this assertion failure while deleting a message.
dovecot: Mar 10 08:40:44 Panic: IMAP(user): file index-sync.c: line 39 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists (&ibox->recent_flags, uid)) dovecot: Mar 10 08:40:44 Error: IMAP(user): Raw backtrace: [see bleow] dovecot: Mar 10 08:40:44 Error: child 17683 (imap) killed with signal 6
And the message doesn't get deleted.
Here one of the backtraces
(gdb) bt #0 0x00ae9402 in __kernel_vsyscall () #1 0x00725ba0 in raise () from /lib/libc.so.6 #2 0x007274b1 in abort () from /lib/libc.so.6 #3 0x080ce02d in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80e1750 "file %s: line %d (%s): assertion failed: (%s)", args=0xbfd8c6a4 "=???\016\b'") at failures.c:424 #4 0x080cdc3c in i_panic (format=0x80e1750 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:187 #5 0x0809bb4a in index_mailbox_set_recent_uid (ibox=0x88ca768, uid=1041) at index-sync.c:39 #6 0x0808085f in mbox_sync_loop (sync_ctx=0xbfd8c8d0, mail_ctx=0xbfd8cac4, partial=true) at mbox-sync.c:457 #7 0x08081361 in mbox_sync (mbox=0x88ca768, flags=18) at mbox-sync.c:1504 #8 0x08079cf9 in mbox_transaction_commit (t=0x88c5550, log_file_seq_r=0xbfd8cbc8, log_file_offset_r=0xbfd8cbc0) at mbox-transaction.c:45 #9 0x0809c69e in index_transaction_commit (_t=0x88cb1c0, uid_validity_r=0xbfd8cc48, first_saved_uid_r=0xbfd8cc44, last_saved_uid_r=0xbfd8cc40) at index-transaction.c:105 #10 0x0805b0cf in cmd_copy (cmd=0x88b75c0) at cmd-copy.c:141 #11 0x0805f079 in cmd_uid (cmd=0x88b75c0) at cmd-uid.c:26 #12 0x0805f9a9 in client_command_input (cmd=0x88b75c0) at client.c:546 #13 0x0805fa3e in client_command_input (cmd=0x88b75c0) at client.c:595 #14 0x080601c5 in client_handle_input (client=0x88b7368) at client.c:636 #15 0x080603de in client_input (client=0x88b7368) at client.c:691 #16 0x080d5ba0 in io_loop_handler_run (ioloop=0x88b59b0) at ioloop-epoll.c:201 #17 0x080d4e28 in io_loop_run (ioloop=0x88b59b0) at ioloop.c:301 #18 0x08067dbc in main (argc=Cannot access memory at address 0x413a ) at main.c:293
(gdb) bt full #0 0x00ae9402 in __kernel_vsyscall () No symbol table info available. #1 0x00725ba0 in raise () from /lib/libc.so.6 No symbol table info available. #2 0x007274b1 in abort () from /lib/libc.so.6 No symbol table info available. #3 0x080ce02d in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80e1750 "file %s: line %d (%s): assertion failed: (%s)", args=0xbfd8c6a4 "=???\016\b'") at failures.c:424 backtrace = 0x88add50 "/usr/libexec/dovecot/imap [0x80ce024] -> /usr/libexec/dovecot/imap [0x80cdc3c] -> /usr/libexec/dovecot/imap [0x809bb4a] -> /usr/libexec/dovecot/imap [0x808085f] -> /usr/libexec/dovecot/imap(mbox_sync+"... #4 0x080cdc3c in i_panic (format=0x80e1750 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:187 args = 0xbfd8c6a4 "=???\016\b'" #5 0x0809bb4a in index_mailbox_set_recent_uid (ibox=0x88ca768, uid=1041) at index-sync.c:39 __PRETTY_FUNCTION__ = "index_mailbox_set_recent_uid" #6 0x0808085f in mbox_sync_loop (sync_ctx=0xbfd8c8d0, mail_ctx=0xbfd8cac4, partial=true) at mbox-sync.c:457 mail = {uid = 268, idx_seq = 133265, keywords = {arr = {buffer = 0x88d3770, element_size = 3218655176}, v = 0x88d3770, v_modifiable = 0x88d3770}, flags = 172 '???', uid_broken = 1, expunged = 0, pseudo = 1, from_offset = 143457960, body_size = 579466361970685888, offset = 143456608, space = 578778797692682360} rec = (const struct mail_index_record *) 0xb7e6f008 uid = 1041 messages_count = 3518 offset = 563 ret = <value optimized out> expunged = false skipped_mails = false uids_broken = false #7 0x08081361 in mbox_sync (mbox=0x88ca768, flags=18) at mbox-sync.c:1504 ret = <value optimized out> #8 0x08079cf9 in mbox_transaction_commit (t=0x88c5550, log_file_seq_r=0xbfd8cbc8, log_file_offset_r=0xbfd8cbc0) at mbox-transaction.c:45 mt = (struct mbox_transaction_context *) 0x88cb1c0 mbox = (struct mbox_mailbox *) 0x88ca768 lock_id = 3 ret = 0 #9 0x0809c69e in index_transaction_commit (_t=0x88cb1c0, uid_validity_r=0xbfd8cc48, first_saved_uid_r=0xbfd8cc44, last_saved_uid_r=0xbfd8cc40) at index-transaction.c:105 itrans = (struct mail_index_transaction *) 0x0 seq = 7 offset = 20544 #10 0x0805b0cf in cmd_copy (cmd=0x88b75c0) at cmd-copy.c:141 client = (struct client *) 0x88b7368 storage = (struct mail_storage *) 0x88b6c80 destbox = (struct mailbox *) 0x88ca768 t = (struct mailbox_transaction_context *) 0x0 search_arg = <value optimized out> messageset = 0x88bb6c0 "224" mailbox = 0x88bb6c8 "Trash" msg = <value optimized out> sync_flags = <value optimized out> imap_flags = <value optimized out> copy_count = 1 uid_validity = <value optimized out> uid1 = <value optimized out> uid2 = <value optimized out> ret = 1 __PRETTY_FUNCTION__ = "cmd_copy" #11 0x0805f079 in cmd_uid (cmd=0x88b75c0) at cmd-uid.c:26 command = (struct command *) 0x6 cmd_name = 0x88bb6b8 "copy" #12 0x0805f9a9 in client_command_input (cmd=0x88b75c0) at client.c:546 client = (struct client *) 0x88b7368 command = <value optimized out> __PRETTY_FUNCTION__ = "client_command_input" #13 0x0805fa3e in client_command_input (cmd=0x88b75c0) at client.c:595 client = (struct client *) 0x88b7368 command = (struct command *) 0x6 __PRETTY_FUNCTION__ = "client_command_input" #14 0x080601c5 in client_handle_input (client=0x88b7368) at client.c:636 _data_stack_cur_id = 3 ret = <value optimized out> remove_io = <value optimized out> handled_commands = false #15 0x080603de in client_input (client=0x88b7368) at client.c:691 cmd = <value optimized out> output = (struct ostream *) 0x88b74ec bytes = 24 __PRETTY_FUNCTION__ = "client_input" #16 0x080d5ba0 in io_loop_handler_run (ioloop=0x88b59b0) at ioloop-epoll.c:201 ctx = <value optimized out> event = (const struct epoll_event *) 0x88b5ae8 list = (struct io_list *) 0x88b7568 io = (struct io_file *) 0x88c0dd0 tv = {tv_sec = 1799, tv_usec = 999737} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #17 0x080d4e28 in io_loop_run (ioloop=0x88b59b0) at ioloop.c:301 No locals. #18 0x08067dbc in main (argc=Cannot access memory at address 0x413a ) at main.c:293 No locals.
Regards, Diego.
On Mon, Mar 10, 2008 at 9:05 AM, Diego Liziero <diegoliz@gmail.com> wrote:
To some users happens this assertion failure while deleting a message.
dovecot: Mar 10 08:40:44 Panic: IMAP(user): file index-sync.c: line 39 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists (&ibox->recent_flags, uid))
36 void index_mailbox_set_recent_uid(struct index_mailbox *ibox, uint32_t uid) 37 { 38 if (uid <= ibox->recent_flags_prev_uid) { 39 i_assert(seq_range_exists(&ibox->recent_flags, uid)); 40 return; 41 } 42 ibox->recent_flags_prev_uid = uid;
Here, when assert fails: uid=1041 ibox->recent_flags_prev_uid = 4557 ibox->recent_flags->arr->element_size = 8 **ibox->recent_flags->v = {seq1 = 4557, seq2 = 4557} (struct seq_range)(ibox->recent_flags->arr->buffer->data) = {seq1 = 143455672, seq2 = 8}
(gdb) print *ibox $16 = {box = {name = 0x88ca8f8 "Trash", storage = 0x88b6c80, v = {is_readonly = 0x809a750 <index_storage_is_readonly>, allow_new_keywords = 0x809a770 <index_storage_allow_new_keywords>, close = 0x8077d50 <mbox_storage_mailbox_close>, get_status = 0x809a620 <index_storage_get_status>, list_index_has_changed = 0, list_index_update_sync = 0, sync_init = 0x80826e0 <mbox_storage_sync_init>, sync_next = 0x809bf00 <index_mailbox_sync_next>, sync_deinit = 0x809bc30 <index_mailbox_sync_deinit>, sync_notify = 0, notify_changes = 0x8077d10 <mbox_notify_changes>, transaction_begin = 0x809c6b0 <index_transaction_begin>, transaction_commit = 0x809c650 <index_transaction_commit>, transaction_rollback = 0x809c630 <index_transaction_rollback>, keywords_create = 0x809a880 <index_keywords_create>, keywords_free = 0x809a790 <index_keywords_free>, get_uids = 0x80934d0 <index_storage_get_uids>, mail_alloc = 0x8094320 <index_mail_alloc>, header_lookup_init = 0x8095d40 <index_header_lookup_init>, header_lookup_deinit = 0x8095c90 <index_header_lookup_deinit>, search_init = 0x8099140 <index_storage_search_init>, search_deinit = 0x8098b50 <index_storage_search_deinit>, search_next_nonblock = 0x8097e40 <index_storage_search_next_nonblock>, search_next_update_seq = 0x8097c10 <index_storage_search_next_update_seq>, save_init = 0x807cab0 <mbox_save_init>, save_continue = 0x807c740 <mbox_save_continue>, save_finish = 0x807c300 <mbox_save_finish>, save_cancel = 0x807c530 <mbox_save_cancel>, copy = 0x809cbd0 <mail_storage_copy>, is_inconsistent = 0x809aa00 <index_storage_is_inconsistent>}, pool = 0x88ca750, transaction_count = 0, private_flags_mask = 0, file_create_mode = 384, dir_create_mode = 448, file_create_gid = 4294967295, notify_min_interval = 0, notify_callback = 0, notify_context = 0x0, module_contexts = {arr = {buffer = 0x88ca900, element_size = 4}, v = 0x88ca900, v_modifiable = 0x88ca900}, opened = 1, mailbox_deleted = 0}, view_module_ctx = {reg = 0x0}, storage = 0x88b6c80, open_flags = 14, index = 0x88c09a8, view = 0x88c3988, cache = 0x88caf50, mail_vfuncs = 0x810aa20, md5hdr_ext_idx = 2, notify_to = 0x0, notify_files = 0x0, notify_ios = 0x0, notify_last_check = 0, notify_last_sent = 0, next_lock_notify = 1205134826, last_notify_type = MAILBOX_LOCK_NOTIFY_NONE, commit_log_file_seq = 7, commit_log_file_offset = 20544, keyword_names = 0x88c0a84, cache_fields = 0x88bf5d8, mail_cache_min_mail_count = 0, recent_flags = {arr = {buffer = 0x88d3758, element_size = 8}, v = 0x88d3758, v_modifiable = 0x88d3758}, recent_flags_prev_uid = 4557, recent_flags_count = 1, sync_last_check = 0, readonly = 0, keep_recent = 1, keep_locked = 0, sent_diskspace_warning = 0, sent_readonly_flags_warning = 0, notify_pending = 0, move_to_memory = 0, fsync_disable = 0}
Diego
Attached the rawlogs while this happens.
I've also a tar.gz of .imap dir of the affected user while this was happening, should I post it, too?
Regards, Diego.
On Mon, 2008-03-10 at 13:17 +0100, Diego Liziero wrote:
On Mon, Mar 10, 2008 at 9:05 AM, Diego Liziero <diegoliz@gmail.com> wrote:
To some users happens this assertion failure while deleting a message.
dovecot: Mar 10 08:40:44 Panic: IMAP(user): file index-sync.c: line 39 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists (&ibox->recent_flags, uid))
Wonder if this fixes it? http://hg.dovecot.org/dovecot-1.1/rev/abc88e664e63
On Wed, Apr 30, 2008 at 4:07 PM, Timo Sirainen <tss@iki.fi> wrote:
On Mon, 2008-03-10 at 13:17 +0100, Diego Liziero wrote:
On Mon, Mar 10, 2008 at 9:05 AM, Diego Liziero <diegoliz@gmail.com> wrote:
To some users happens this assertion failure while deleting a message.
dovecot: Mar 10 08:40:44 Panic: IMAP(user): file index-sync.c: line 39 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists (&ibox->recent_flags, uid))
Wonder if this fixes it? http://hg.dovecot.org/dovecot-1.1/rev/abc88e664e63
Just updated to current tree. I'll let you know if it happens again.
Here are some more errors I got in dovecot.log with 1.1.rc4: Corrupted index cache file /path/to/dovecot.index.cache: Broken MIME parts for mail UID uidnumber Corrupted index cache file /path/to/dovecot.index.cache: Broken virtual size for mail UID uidnumber Corrupted index cache file /path/to/dovecot.index.cache: used_file_size too large FETCH for mailbox mailboxname UID uidnumber got too little data: a vs a+b UIDs broken with partial sync in mbox file Corrupted transaction log file /path/to/dovecot.index.log: record size too small (type=0x40, offset=7576, size=0) Log synchronization error at seq=1,offset=24 for /path/to/dovecot.index: Broken extension introduction: Record field points outside record size (0+16
Diego.
On Wed, Apr 30, 2008 at 4:07 PM, Timo Sirainen <tss@iki.fi> wrote:
On Mon, Mar 10, 2008 at 9:05 AM, Diego Liziero wrote:
To some users happens this assertion failure while deleting a message.
dovecot: Mar 10 08:40:44 Panic: IMAP(user): file index-sync.c: line 39 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists (&ibox->recent_flags, uid))
Wonder if this fixes it? http://hg.dovecot.org/dovecot-1.1/rev/abc88e664e63
Unfortunately not. Got it again this morning (I only changed i_assert with i_error): dovecot: May 02 09:40:39 Error: IMAP(username): seq_range_exists(&ibox->recent_flags, uid)
Timo, I was wondering If I can help you in spotting the cause of this assertion failure (got this morning with rc5) adding some i_info/debug and other seq_range_exists tests.
This morning all assertion failures were caused by users that deleted with thunderbird many emails from inbox and thunderbird tried to move them to imap trash folder.
seq_range_exists(&ibox->recent_flags, uid)
Regards, Diego.
participants (2)
-
Diego Liziero
-
Timo Sirainen