dovecot - Jul 2005 - Assertion failure in mail-index-transaction.c

I just noticed one instance of this in the current CVS version:


dovecot: Jul 18 15:25:48 Error:  5962 IMAP(mailuser): mbox sync: Expunged
message reappeared in mailbox /mailhome/new/o/h/mailuser/mbox (UID 2834
< 2872)

dovecot: Jul 18 15:25:48 Error:  5962 IMAP(mailuser): file
mail-index-transaction.c: line 129 (mail_index_buffer_convert_to_uids):
assertion failed: (*seq != 0)

dovecot: Jul 18 15:25:48 Error: child 5962 (imap) killed with signal 6

(gdb) bt full
#0  0xffffe410 in ?? ()
No symbol table info available.
#1  0xbffff438 in ?? ()
No symbol table info available.
#2  0x00000006 in ?? ()
No symbol table info available.
#3  0x0000174a in ?? ()
No symbol table info available.
#4  0xb7ef1d41 in raise () from /lib/tls/libc.so.6
No symbol table info available.
#5  0xb7ef3529 in abort () from /lib/tls/libc.so.6
No symbol table info available.
#6  0x0809a96a in i_internal_panic_handler (
     fmt=0x6 <Address 0x6 out of bounds>,
     args=0x174a <Address 0x174a out of bounds>) at failures.c:374
No locals.
#7  0x0809ad84 in i_panic (
     format=0x80a772c "file %s: line %d (%s): assertion failed: (%s)")
     at failures.c:173
No locals.
#8  0x08082711 in mail_index_buffer_convert_to_uids (t=0x80d14b8,
     array=0x80d14d0, range=1) at mail-index-transaction.c:129
         view = (struct mail_index_view *) 0x80cfdc0
         rec = Variable "rec" is not available.


(gdb) bt
#0  0xffffe410 in ?? ()
#1  0xbffff438 in ?? ()
#2  0x00000006 in ?? ()
#3  0x0000174a in ?? ()
#4  0xb7ef1d41 in raise () from /lib/tls/libc.so.6
#5  0xb7ef3529 in abort () from /lib/tls/libc.so.6
#6  0x0809a96a in i_internal_panic_handler (
     fmt=0x6 <Address 0x6 out of bounds>,
     args=0x174a <Address 0x174a out of bounds>) at failures.c:374
#7  0x0809ad84 in i_panic (
     format=0x80a772c "file %s: line %d (%s): assertion failed: (%s)")
     at failures.c:173
#8  0x08082711 in mail_index_buffer_convert_to_uids (t=0x80d14b8,
     array=0x80d14d0, range=1) at mail-index-transaction.c:129
#9  0x08083b87 in mail_index_transaction_commit (t=0x80d14b8,
     log_file_seq_r=0xbffff65c, log_file_offset_r=0xbffff660)
     at mail-index-transaction.c:183
#10 0x080703f4 in mbox_sync (mbox=0x80c5bc0, flags=Variable "flags" is
not available.
) at mbox-sync.c:1623
#11 0x080710c9 in mbox_storage_sync_init (box=0x80c5bc0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at mbox-sync.c:1700
#12 0x0808ef01 in mailbox_sync_init (box=0x0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at mail-storage.c:334
#13 0x0805eb58 in imap_sync_nonselected (box=0x80c5bc0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at imap-sync.c:166
#14 0x080580f6 in _cmd_select_full (cmd=0x80beba8, readonly=0)
     at cmd-select.c:39
#15 0x08058281 in cmd_select (cmd=0x80beba8) at cmd-select.c:92
#16 0x0805986b in _client_input (context=0x80beb68) at client.c:334
#17 0x0809ff3a in io_loop_handler_run (ioloop=0x80bd9b0) at ioloop-poll.c:184
#18 0x0809f569 in io_loop_run (ioloop=0x80bd9b0) at ioloop.c:218
#19 0x08060657 in main (argc=1, argv=0xbffffa34, envp=0xbffffa3c) at main.c:228


(gdb) p seq
$1 = (uint32_t *) 0x80d4d18
(gdb) p *seq
$2 = 0
(gdb) p view->map
$3 = (struct mail_index_map *) 0x80c5fd0
(gdb) p *view->map
$4 = {refcount = 3, hdr = {major_version = 7 '\a', minor_version = 0
'\0',
     base_header_size = 120, header_size = 200, record_size = 36,
     compat_data = "\001\b\004", indexid = 1113829460, flags = 0,
     uid_validity = 1113827022, next_uid = 2872, messages_count = 929,
     recent_messages_count = 0, seen_messages_count = 810,
     deleted_messages_count = 0, first_recent_uid_lowwater = 0,
     first_unseen_uid_lowwater = 1149, first_deleted_uid_lowwater = 2846,
     log_file_seq = 8, log_file_int_offset = 27912,
     log_file_ext_offset = 27912, sync_size = 9241460, sync_stamp = 1113863658,
     day_stamp = 1121659200, day_first_uid = {2855, 2849, 2849, 2753, 2753,
       2753, 2491, 187}}, hdr_base = 0x80c60b0, records = 0x80c61d8,
   records_count = 929, extension_pool = 0x80ce490, extensions = {
     buffer = 0x80ce4c0, element_size = 28}, ext_id_map = {buffer = 0x80ce588,
     element_size = 4}, mmap_base = 0x0, mmap_size = 0, mmap_used_size = 0,
   buffer = 0x80c61b8, hdr_copy_buf = 0x80c6090, keyword_idx_map = {
     buffer = 0x0, element_size = 0}, write_to_disk = 0}
(gdb) p t
$5 = (struct mail_index_transaction *) 0x80d14b8
(gdb) p *t
$6 = {refcount = 1, view = 0x80cfdc0, appends = {buffer = 0x80d4830,
     element_size = 8}, first_new_seq = 930, last_new_seq = 953, expunges = {
     buffer = 0x80d4810, element_size = 8}, updates = {buffer = 0x0,
     element_size = 0}, last_update_idx = 0,
   pre_hdr_change = '\0' <repeats 119 times>,
   pre_hdr_mask = '\0' <repeats 119 times>,
   post_hdr_change = '\0' <repeats 28 times>, "O\v",
'\0' <repeats 89 times>,
   post_hdr_mask = '\0' <repeats 28 times>,
"\001\001\001\001", '\0' <repeats 87 times>,
ext_rec_updates = {buffer = 0x80d4750, element_size = 8},
   ext_resizes = {buffer = 0x0, element_size = 0}, ext_resets = {buffer = 0x0,
     element_size = 0}, keyword_updates = {buffer = 0x0, element_size = 0},
   keyword_resets = {buffer = 0x80d4730, element_size = 8},
   cache_trans_ctx = 0x0, hide_transaction = 0, no_appends = 0, external = 1,
   pre_hdr_changed = 0, post_hdr_changed = 1, log_updates = 1}
(gdb) p j
$7 = 2
(gdb) p range
$8 = 1

On Mon, 2005-07-18 at 17:52 -0400, Todd Burroughs wrote:
> I just noticed one instance of this in the current CVS version:
> 
> 
> dovecot: Jul 18 15:25:48 Error:  5962 IMAP(mailuser): mbox sync: Expunged
> message reappeared in mailbox /mailhome/new/o/h/mailuser/mbox (UID 2834
> < 2872)
I made some changes to the code which caused this. The check for this
error was actually wrong, and I don't think this error should ever have
actually occured. I added an extra assert there, so it probably starts
crashing in that assert the next time it happens. Then it would be nice
to get these variables:

p *sync_ctx.sync_view.map
p *sync_ctx.sync_view.index.map

You were running with mmap_disable=yes I think?

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20050723/75b450c1/attachment-0001.bin>

This just started happening with the current CVS version (2005-07-23).
The "user" is a monitoring tool that we use called Sitescope.  It has
been
monitoring dovecot for a long time and I've never seen an error before
this.  Deleting the .imap directory seems to have resolved the problem.
This did not start until several hours into running the new version.


dovecot: Jul 25 19:45:38 Error:  16590 IMAP(sitescope): file 
mail-index-transaction.c: line 588 (mail_index_update_flags_range):
  assertion failed: (seq1 <= seq2 && seq1 > 0)

dovecot: Jul 25 19:45:39 Error: child 16590 (imap) killed with signal 6

(gdb) bt full
#0  0xffffe410 in ?? ()
No symbol table info available.
#1  0xbffff2c8 in ?? ()
No symbol table info available.
#2  0x00000006 in ?? ()
No symbol table info available.
#3  0x00004207 in ?? ()
No symbol table info available.
#4  0xb7ef1d41 in raise () from /lib/tls/libc.so.6
No symbol table info available.
#5  0xb7ef3529 in abort () from /lib/tls/libc.so.6
No symbol table info available.
#6  0x0809acca in i_internal_panic_handler (
     fmt=0x6 <Address 0x6 out of bounds>,
     args=0x4207 <Address 0x4207 out of bounds>) at failures.c:374
No locals.
#7  0x0809b0e4 in i_panic (
     format=0x80a7a8c "file %s: line %d (%s): assertion failed: (%s)")
     at failures.c:173
No locals.
#8  0x08083411 in mail_index_update_flags_range (t=0x80d2320, seq1=0, seq2=0,
     modify_type=MODIFY_ADD, flags=128) at array.h:99
         rec = Variable "rec" is not available.


(gdb) bt
#0  0xffffe410 in ?? ()
#1  0xbffff2c8 in ?? ()
#2  0x00000006 in ?? ()
#3  0x00004207 in ?? ()
#4  0xb7ef1d41 in raise () from /lib/tls/libc.so.6
#5  0xb7ef3529 in abort () from /lib/tls/libc.so.6
#6  0x0809acca in i_internal_panic_handler (
     fmt=0x6 <Address 0x6 out of bounds>,
     args=0x4207 <Address 0x4207 out of bounds>) at failures.c:374
#7  0x0809b0e4 in i_panic (
     format=0x80a7a8c "file %s: line %d (%s): assertion failed: (%s)")
     at failures.c:173
#8  0x08083411 in mail_index_update_flags_range (t=0x80d2320, seq1=0, seq2=0,
     modify_type=MODIFY_ADD, flags=128) at array.h:99
#9  0x0806e262 in mbox_sync_read_index_syncs (sync_ctx=0xbffff710, uid=1,
     sync_expunge_r=0xbffff58c) at mbox-sync.c:213
#10 0x0806ec1e in mbox_sync_loop (sync_ctx=0xbffff710, mail_ctx=0xbffff680,
     partial=Variable "partial" is not available.
) at mbox-sync.c:1070
#11 0x080704c0 in mbox_sync (mbox=0x80c4bc0, flags=Variable "flags" is
not available.
) at mbox-sync.c:1441
#12 0x08071379 in mbox_storage_sync_init (box=0x80c4bc0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at mbox-sync.c:1766
#13 0x0808f221 in mailbox_sync_init (box=0x0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at mail-storage.c:334
#14 0x0805ed08 in imap_sync_nonselected (box=0x80c4bc0,
     flags=MAILBOX_SYNC_FLAG_FULL_READ) at imap-sync.c:171
#15 0x08058166 in _cmd_select_full (cmd=0x80beba8, readonly=0)
     at cmd-select.c:39
#16 0x080582f1 in cmd_select (cmd=0x80beba8) at cmd-select.c:92
#17 0x0805997b in _client_input (context=0x80beb68) at client.c:334
#18 0x080a029a in io_loop_handler_run (ioloop=0x80bd9b0) at ioloop-poll.c:184
#19 0x0809f8c9 in io_loop_run (ioloop=0x80bd9b0) at ioloop.c:218
#20 0x08060847 in main (argc=1, argv=0xbffffa24, envp=0xbffffa2c) at main.c:229


(gdb) p seq1
$1 = 0
(gdb) p seq2
$2 = 0
(gdb) p *t
$3 = {refcount = 1, view = 0x80d0120, appends = {buffer = 0x0,
     element_size = 0}, first_new_seq = 466, last_new_seq = 0, expunges = {
     buffer = 0x0, element_size = 0}, updates = {buffer = 0x0,
     element_size = 0}, last_update_idx = 0,
   pre_hdr_change = '\0' <repeats 119 times>,
   pre_hdr_mask = '\0' <repeats 119 times>,
   post_hdr_change = '\0' <repeats 119 times>,
   post_hdr_mask = '\0' <repeats 119 times>, ext_rec_updates =
{buffer = 0x0,
     element_size = 0}, ext_resizes = {buffer = 0x0, element_size = 0},
   ext_resets = {buffer = 0x0, element_size = 0}, keyword_updates = {
     buffer = 0x0, element_size = 0}, keyword_resets = {buffer = 0x0,
     element_size = 0}, cache_trans_ctx = 0x0, hide_transaction = 0,
   no_appends = 0, external = 1, pre_hdr_changed = 0, post_hdr_changed = 0,
   log_updates = 1}