[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 ,
allow_new_keywords = 0x809a770
, close = 0x8077d50
,
get_status = 0x809a620 ,
list_index_has_changed = 0, list_index_update_sync = 0,
sync_init = 0x80826e0 , sync_next =
0x809bf00 ,
sync_deinit = 0x809bc30 , sync_notify
= 0, notify_changes = 0x8077d10 ,
transaction_begin = 0x809c6b0 ,
transaction_commit = 0x809c650 ,
transaction_rollback = 0x809c630 ,
keywords_create = 0x809a880 ,
keywords_free = 0x809a790 , get_uids =
0x80934d0 ,
mail_alloc = 0x8094320 , header_lookup_init =
0x8095d40 ,
header_lookup_deinit = 0x8095c90 ,
search_init = 0x8099140 ,
search_deinit = 0x8098b50 ,
search_next_nonblock = 0x8097e40 ,
search_next_update_seq = 0x8097c10
, save_init = 0x807cab0
,
save_continue = 0x807c740 , save_finish =
0x807c300 ,
save_cancel = 0x807c530 , copy = 0x809cbd0
,
is_inconsistent = 0x809aa00 },
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