diff -r b7fcace54fad src/lib-index/mail-index-map.c
--- a/src/lib-index/mail-index-map.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-index/mail-index-map.c	Fri May 30 01:50:32 2008 +0300
@@ -94,6 +94,9 @@
 	ext->record_size = ext_hdr->record_size;
 	ext->record_align = ext_hdr->record_align;
 	ext->reset_id = ext_hdr->reset_id;
+
+	i_debug("map %p: ext_id=%u name=%s reset_id=%u",
+		map, idx, name, ext->reset_id);
 
 	ext->index_idx = mail_index_ext_register(map->index, name,
 						 ext_hdr->hdr_size,
diff -r b7fcace54fad src/lib-index/mail-index-sync-ext.c
--- a/src/lib-index/mail-index-sync-ext.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-index/mail-index-sync-ext.c	Fri May 30 01:50:32 2008 +0300
@@ -426,6 +426,7 @@
 			/* extension was reset and this transaction hadn't
 			   yet seen it. ignore this update (except for
 			   resets). */
+			i_debug("ext ignore: %u != %u", u->reset_id, ext->reset_id);
 			ctx->cur_ext_ignore = TRUE;
 		}
 
@@ -517,6 +518,7 @@
 
 	ext = array_idx_modifiable(&map->extensions, ctx->cur_ext_map_idx);
 	ext->reset_id = u->new_reset_id;
+	i_debug("sync reset: new_reset_id=%u", ext->reset_id);
 
 	if (!u->preserve_data)
 		mail_index_sync_ext_clear(ctx->view, map, ext);
diff -r b7fcace54fad src/lib-index/mail-index-sync-update.c
--- a/src/lib-index/mail-index-sync-update.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-index/mail-index-sync-update.c	Fri May 30 01:50:32 2008 +0300
@@ -785,6 +785,7 @@
 
 	mail_transaction_log_view_get_prev_pos(view->log_view,
 					       &prev_seq, &prev_offset);
+	i_debug("map %p: start syncing at %u type=%d", map, prev_offset, type);
 
 	mail_index_sync_map_init(&sync_map_ctx, view, type);
 	if (reset) {
@@ -829,6 +830,8 @@
 		} T_END;
 	}
 	map = view->map;
+
+	i_debug("map %p: stop syncing at %u", map, prev_offset);
 
 	if (had_dirty)
 		mail_index_sync_update_hdr_dirty_flag(map);
diff -r b7fcace54fad src/lib-index/mail-index-transaction.c
--- a/src/lib-index/mail-index-transaction.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-index/mail-index-transaction.c	Fri May 30 01:50:32 2008 +0300
@@ -29,6 +29,8 @@
 	ARRAY_TYPE(seq_array) *recs;
 	struct mail_index_transaction_ext_hdr_update **ext_hdrs;
 	unsigned i, count;
+
+	i_debug("transaction: reset");
 
 	if (array_is_created(&t->ext_rec_updates)) {
 		recs = array_get_modifiable(&t->ext_rec_updates, &count);
diff -r b7fcace54fad src/lib-index/mail-transaction-log-append.c
--- a/src/lib-index/mail-transaction-log-append.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-index/mail-transaction-log-append.c	Fri May 30 01:50:32 2008 +0300
@@ -183,9 +183,11 @@
 	}
 	if (reset_id != expected_reset_id) {
 		/* ignore this extension update */
+		i_debug("transaction: discarded atomic %u != %u", reset_id, expected_reset_id);
 		mail_index_ext_set_reset_id(t, ext_id, 0);
 		return;
 	}
+	i_debug("transaction: commit atomic %u", reset_id);
 
 	if (reset_id == 0)
 		reset_id++;
@@ -556,12 +558,19 @@
 		if (mail_index_map(t->view->index,
 				   MAIL_INDEX_SYNC_HANDLER_HEAD) <= 0)
 			return -1;
+		i_debug("transaction: read up to %u, hdr.head=%u",
+			(int)log->head->sync_offset,
+			t->view->index->map->hdr.log_file_head_offset);
 		transaction_update_atomic_reset_ids(t);
 
 		if (!TRANSACTION_HAS_CHANGES(t)) {
 			/* we aborted the ext changes, nothing else to do */
 			return 0;
 		}
+	} else {
+		i_debug("transaction: non-atomic read up to %u, hdr.head=%u",
+			(int)log->head->sync_offset,
+			t->view->index->map->hdr.log_file_head_offset);
 	}
 
 	file = log->head;
@@ -656,6 +665,7 @@
 
 	*log_file_seq_r = file->hdr.file_seq;
 	*log_file_offset_r = file->sync_offset;
+	i_debug("transaction: written to %u..%u", append_offset, (int)file->sync_offset);
 	return 0;
 }
 
diff -r b7fcace54fad src/lib-storage/index/index-sort-string.c
--- a/src/lib-storage/index/index-sort-string.c	Thu May 29 19:11:32 2008 +0300
+++ b/src/lib-storage/index/index-sort-string.c	Fri May 30 01:50:32 2008 +0300
@@ -44,6 +44,32 @@
 static char expunged_msg;
 static struct sort_string_context *static_zero_cmp_context;
 static struct mail_search_sort_program *static_sort_node_cmp_context;
+#include <sys/time.h>
+#include <stdio.h>
+#include <unistd.h>
+#include "ioloop.h"
+void i_debug(const char *format, ...)
+{
+	static FILE *f = NULL;
+	va_list args;
+	struct timeval tv;
+
+	gettimeofday(&tv, NULL);
+
+	va_start(args, format);
+	t_push();
+	if (!f) {
+		const char *dir = t_strdup_printf("/tmp/dovecot/%d", (int)ioloop_time/10);
+		mkdir(dir, 0700);
+		f = fopen(t_strdup_printf("%s/%d", dir, getpid()), "a+");
+		setbuf(f, NULL);
+	}
+	fprintf(f, "%10u.%06u PID=%s %s\n",
+		(unsigned)tv.tv_sec, (unsigned)tv.tv_usec,
+		dec2str(getpid()), t_strdup_vprintf(format, args));
+	t_pop();
+	va_end(args);
+}
 
 static void index_sort_node_add(struct sort_string_context *ctx,
 				struct mail_sort_node *node);
@@ -78,13 +104,15 @@
 					      sizeof(uint32_t));
 	i_array_init(&ctx->zero_nodes, 128);
 	i_array_init(&ctx->nonzero_nodes, 128);
+
+	i_debug("-------------- init ----------");
 }
 
 static void index_sort_generate_seqs(struct sort_string_context *ctx)
 {
 	struct mail_sort_node *nodes, *nodes2;
 	unsigned int i, j, count, count2;
-	uint32_t seq;
+	uint32_t seq, prev_seq = 0;
 
 	nodes = array_get_modifiable(&ctx->nonzero_nodes, &count);
 	nodes2 = array_get_modifiable(&ctx->zero_nodes, &count2);
@@ -107,6 +135,8 @@
 		} else {
 			break;
 		}
+		i_assert(seq > prev_seq);
+		prev_seq = seq;
 		array_append(&ctx->program->seqs, &seq, 1);
 	}
 }
@@ -116,6 +146,11 @@
 	struct mail_sort_node node;
 	const uint32_t *seqs;
 	unsigned int i, count;
+
+	if (array_count(&ctx->zero_nodes) == 0 &&
+	    array_count(&ctx->nonzero_nodes) == 0)
+		return;
+	i_debug("--- reget ---");
 
 	i_assert(!ctx->regetting);
 	ctx->regetting = TRUE;
@@ -141,7 +176,7 @@
 		(struct index_transaction_context *)ctx->program->t;
 	struct mail_index_map *map;
 	const void *data;
-	uint32_t reset_id;
+	uint32_t reset_id, uid;
 	bool expunged;
 
 	mail_index_lookup_ext_full(t->trans_view, node->seq,
@@ -183,18 +218,25 @@
 				   the node lists aren't ordered by sequence
 				   anymore. */
 				node->sort_id = 0;
+				if (!ctx->no_writing)
+					i_debug(" --> no writing=true");
 				ctx->no_writing = TRUE;
 			} else {
+				i_debug(" --> reset_id %u -> %u", ctx->highest_reset_id, reset_id);
 				ctx->highest_reset_id = reset_id;
 				index_sort_reget_sort_ids(ctx);
 			}
 		}
 	}
 
-	if (node->sort_id == 0)
+	mail_index_lookup_uid(t->trans_view, node->seq, &uid); //FIXME
+	if (node->sort_id == 0) {
+		i_debug("seq=%u uid=%u add zero expunged=%d", node->seq, uid, expunged);
 		array_append(&ctx->zero_nodes, node, 1);
-	else
+	} else {
+		i_debug("seq=%u uid=%u add sort_id=%u", node->seq, uid, node->sort_id);
 		array_append(&ctx->nonzero_nodes, node, 1);
+	}
 	if (ctx->last_seq < node->seq)
 		ctx->last_seq = node->seq;
 }
@@ -333,6 +375,44 @@
 	return ctx->sort_strings[seq];
 }
 
+static void check(struct sort_string_context *ctx)
+{
+	struct index_transaction_context *t =
+		(struct index_transaction_context *)ctx->program->t;
+	struct mail_sort_node *nodes;
+	const char *prev_str, *str;
+	unsigned int i, count, prev_id = 0;
+	uint32_t uid, prev_uid = 0;
+	int ret;
+
+	nodes = array_get_modifiable(&ctx->sorted_nodes, &count);
+	prev_str = &expunged_msg;
+	for (i = 0; i < count && prev_str == &expunged_msg; i++) {
+		prev_str = index_sort_get_string(ctx, i, nodes[i].seq);
+		if (nodes[i].sort_id != 0) {
+			mail_index_lookup_uid(t->trans_view, nodes[i].seq, &prev_uid);
+			prev_id = nodes[i].sort_id;
+		}
+	}
+	for (; i < count; i++) {
+		mail_index_lookup_uid(t->trans_view, nodes[i].seq, &uid);
+		str = index_sort_get_string(ctx, i, nodes[i].seq);
+		if (str != &expunged_msg) {
+			ret = strcmp(prev_str, str);
+			i_assert(ret <= 0);
+			i_assert(ret < 0 || nodes[i].sort_id == 0 ||
+				 nodes[i-1].sort_id == 0 ||
+				 prev_id == nodes[i].sort_id);
+			prev_str = str;
+		}
+		if (nodes[i].sort_id != 0) {
+			i_assert(prev_id <= nodes[i].sort_id);
+			prev_id = nodes[i].sort_id;
+			prev_uid = uid;
+		}
+	}
+}
+
 static void
 index_sort_bsearch(struct sort_string_context *ctx, const char *key,
 		   unsigned int start_idx, unsigned int *idx_r,
@@ -438,6 +518,7 @@
 			prev_str = nzstr;
 			nzpos++;
 
+#if 1
 			/* avoid looking up all existing messages' strings by
 			   binary searching the next zero-node position. don't
 			   bother if it looks like more work than linear
@@ -445,11 +526,13 @@
 			if (zcount - zpos < (nzcount - nzpos)/2) {
 				index_sort_bsearch(ctx, zstr, nzpos,
 						   &nz_next_pos, &prev_str);
+				i_assert(nz_next_pos >= nzpos);
 				array_append(&ctx->sorted_nodes,
 					     &nznodes[nzpos],
 					     nz_next_pos - nzpos);
 				nzpos = nz_next_pos;
 			}
+#endif
 		}
 	}
 	/* only one of zero_nodes and nonzero_nodes can be non-empty now */
@@ -462,6 +545,8 @@
 	   use only ctx->sorted_nodes. make them identical. */
 	array_free(&ctx->nonzero_nodes);
 	ctx->nonzero_nodes = ctx->sorted_nodes;
+
+	check(ctx);
 }
 
 static void
@@ -469,10 +554,13 @@
 			 unsigned int left_idx, unsigned int right_idx)
 {
 
+	struct index_transaction_context *t =
+		(struct index_transaction_context *)ctx->program->t;
 	struct mail_sort_node *nodes;
 	unsigned int i, count, rightmost_idx, skip;
 	const char *left_str = NULL, *right_str = NULL, *str;
 	uint32_t left_sort_id, right_sort_id;
+	uint32_t uid; //FIXME
 
 	nodes = array_get_modifiable(&ctx->sorted_nodes, &count);
 	rightmost_idx = count - 1;
@@ -546,25 +634,35 @@
 	}
 	i_assert(left_idx <= right_idx);
 
+	i_debug("idx=%u..%u: left_str=%s right_str=%s",
+		left_idx, right_idx, left_str, right_str);
+
 	/* give (new) sort IDs to all nodes in left_idx..right_idx range.
 	   divide the available space so that each message gets an equal sized
 	   share. some messages' sort strings may be equivalent, so give them
 	   the same sort IDs. */
 	for (i = left_idx; i <= right_idx; i++) {
+		mail_index_lookup_uid(t->trans_view, nodes[i].seq, &uid);
 		str = index_sort_get_string(ctx, i, nodes[i].seq);
 		if (str == &expunged_msg) {
 			/* it doesn't really matter what we give to this
 			   message, since it's only temporary and we don't
 			   know its correct position anyway. so let's assume
 			   it's equivalent to previous message. */
+			i_debug("seq=%u uid=%u set expunged sort_id=%u",
+				nodes[i].seq, uid, left_sort_id);
 			nodes[i].sort_id = left_sort_id;
 			continue;
 		}
 
-		if (left_str != NULL && strcmp(str, left_str) == 0)
+		if (left_str != NULL && strcmp(str, left_str) == 0) {
+			i_debug("seq=%u uid=%u set left sort_id=%u",
+				nodes[i].seq, uid, left_sort_id);
 			nodes[i].sort_id = left_sort_id;
-		else if (right_str != NULL && strcmp(str, right_str) == 0) {
+		} else if (right_str != NULL && strcmp(str, right_str) == 0) {
 			/* the rest of the sort IDs should be the same */
+			i_debug("seq=%u uid=%u set right sort_id=%u",
+				nodes[i].seq, uid, right_sort_id);
 			nodes[i].sort_id = right_sort_id;
 			left_sort_id = right_sort_id;
 		} else {
@@ -581,11 +679,15 @@
 			left_sort_id += skip;
 			i_assert(left_sort_id < right_sort_id);
 
+			i_debug("seq=%u uid=%u set inc sort_id=%u str=%s",
+				nodes[i].seq, uid, left_sort_id, str);
+
 			nodes[i].sort_id = left_sort_id;
 			left_str = str;
 		}
 		nodes[i].sort_id_changed = TRUE;
 	}
+	check(ctx);
 }
 
 static void
@@ -594,6 +696,7 @@
 	const struct mail_sort_node *nodes;
 	unsigned int i, left_idx, right_idx, count;
 
+	check(ctx);
 	nodes = array_get(&ctx->sorted_nodes, &count);
 	for (i = 0; i < count; i++) {
 		if (nodes[i].sort_id != 0)
@@ -610,6 +713,7 @@
 		left_idx = i == 0 ? 0 : i - 1;
 		index_sort_add_ids_range(ctx, left_idx, right_idx);
 	}
+	check(ctx);
 }
 
 static void index_sort_write_changed_sort_ids(struct sort_string_context *ctx)
@@ -618,8 +722,10 @@
 		(struct index_transaction_context *)ctx->program->t;
 	uint32_t ext_id = ctx->ext_id;
 	const struct mail_sort_node *nodes;
+	uint32_t uid;
 	unsigned int i, count;
 
+	i_debug("writing: old reset id = %u", ctx->highest_reset_id);
 	if (ctx->no_writing) {
 		/* our reset_id is already stale - don't even bother
 		   trying to write */
@@ -632,8 +738,15 @@
 	nodes = array_get_modifiable(&ctx->sorted_nodes, &count);
 	for (i = 0; i < count; i++) {
 		i_assert(nodes[i].sort_id != 0);
-		if (!nodes[i].sort_id_changed || nodes[i].no_update)
+		mail_index_lookup_uid(t->trans_view, nodes[i].seq, &uid); //FIXME
+		if (!nodes[i].sort_id_changed || nodes[i].no_update) {
+			i_debug("seq=%u uid=%u skip: changed=%d no_update=%d sort_id=%u",
+				nodes[i].seq, uid, nodes[i].sort_id_changed, nodes[i].no_update, nodes[i].sort_id);
 			continue;
+		}
+
+		i_debug("seq=%u uid=%u write sort_id=%u",
+			nodes[i].seq, uid, nodes[i].sort_id);
 
 		mail_index_update_ext(t->trans, nodes[i].seq, ext_id,
 				      &nodes[i].sort_id, NULL);
@@ -657,6 +770,8 @@
 
 static void index_sort_add_missing(struct sort_string_context *ctx)
 {
+	struct index_transaction_context *t =
+		(struct index_transaction_context *)ctx->program->t;
 	struct mail_sort_node node;
 	const uint32_t *seqs;
 	unsigned int i, count;
@@ -679,6 +794,9 @@
 		}
 	}
 
+	i_debug("all missing added, msgs=%u, lowest_nonexpunged_zero=%u",
+		t->ibox->view->map->hdr.messages_count,
+		ctx->lowest_nonexpunged_zero);
 	if (ctx->lowest_nonexpunged_zero == 0) {
 		/* we're handling only expunged zeros. if it causes us to
 		   renumber some existing sort IDs, don't save them. */
@@ -692,6 +810,8 @@
 	struct mail_sort_node *nodes;
 	unsigned int i, count;
 	uint32_t seq;
+
+	i_debug("-------------- finishing ----------");
 
 	nodes = array_get_modifiable(&ctx->nonzero_nodes, &count);