diff -r 96c8632775df src/lib-index/mail-index-sync-update.c --- a/src/lib-index/mail-index-sync-update.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-index-sync-update.c Mon May 04 16:35:01 2009 -0400 @@ -227,6 +227,19 @@ } } +static const char *sync_type(struct mail_index_sync_map_ctx *ctx) +{ + switch (ctx->type) { + case MAIL_INDEX_SYNC_HANDLER_FILE: + return "sync=file"; + case MAIL_INDEX_SYNC_HANDLER_HEAD: + return "sync=head"; + case MAIL_INDEX_SYNC_HANDLER_VIEW: + return "sync=view"; + } + return "sync=????"; +} + static int sync_expunge(const struct mail_transaction_expunge *e, unsigned int count, struct mail_index_sync_map_ctx *ctx) @@ -236,13 +249,21 @@ uint32_t seq_count, seq, seq1, seq2; unsigned int i; + i_debug("%s: sync_expunge", sync_type(ctx)); for (i = 0; i < count; i++, e++) { + for (seq = e->uid1; seq <= e->uid2; seq++) + i_debug("%s: sync_expunge: uid=%u", sync_type(ctx), seq); if (!mail_index_lookup_seq_range(ctx->view, e->uid1, e->uid2, &seq1, &seq2)) { /* everything expunged already */ continue; } + for (seq = seq1; seq <= seq2; seq++) { + rec = MAIL_INDEX_MAP_IDX(map, seq-1); + i_debug("%s: sync_expunge loop: uid=%u", sync_type(ctx), rec->uid); + } + i_debug("%s: ---", sync_type(ctx)); sync_expunge_call_handlers(ctx, seq1, seq2); map = mail_index_sync_get_atomic_map(ctx); @@ -460,6 +481,9 @@ case MAIL_TRANSACTION_EXPUNGE|MAIL_TRANSACTION_EXPUNGE_PROT: { const struct mail_transaction_expunge *rec = data, *end; + i_debug("%s: expunge: external = %d", sync_type(ctx), + (hdr->type & MAIL_TRANSACTION_EXTERNAL) != 0); + if ((hdr->type & MAIL_TRANSACTION_EXTERNAL) == 0) { /* this is simply a request for expunge */ break; @@ -788,6 +812,8 @@ mail_transaction_log_view_get_prev_pos(view->log_view, &prev_seq, &prev_offset); + i_debug("mail_index_sync_map: begin"); + mail_index_sync_map_init(&sync_map_ctx, view, type); if (reset) { /* Reset the entire index. Leave only indexid and @@ -866,6 +892,11 @@ i_assert(index->map == map || type == MAIL_INDEX_SYNC_HANDLER_VIEW); + i_debug("mail_index_sync_map: finished " + "seq=%u head_offset=%u tail_offset=%u", + map->hdr.log_file_seq, map->hdr.log_file_head_offset, + map->hdr.log_file_tail_offset); + if (mail_index_map_check_header(map) <= 0) { mail_index_set_error(index, "Synchronization corrupted index header: %s", diff -r 96c8632775df src/lib-index/mail-index-sync.c --- a/src/lib-index/mail-index-sync.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-index-sync.c Mon May 04 16:35:01 2009 -0400 @@ -197,6 +197,7 @@ /* read all transactions from log into a transaction in memory. skip the external ones, they're already synced to mailbox and included in our view */ + i_debug("read_and_sort"); while ((ret = mail_transaction_log_view_next(ctx->view->log_view, &ctx->hdr, &ctx->data)) > 0) { @@ -208,6 +209,7 @@ mail_index_sync_update_mailbox_pos(ctx); } T_END; } + i_debug("/read_and_sort"); /* create an array containing all expunge, flag and keyword update arrays so we can easily go through all of the changes. */ @@ -331,11 +333,13 @@ uint32_t log_file_seq, uoff_t log_file_offset) { const struct mail_index_header *hdr; - uint32_t seq; - uoff_t offset; + uint32_t seq = 0; + uoff_t offset = 0; bool locked = FALSE; int ret; + i_debug("mail_index_sync_begin_init"); + /* if we require changes, don't lock transaction log yet. first check if there's anything to sync. */ if ((flags & MAIL_INDEX_SYNC_FLAG_REQUIRE_CHANGES) == 0) { @@ -383,6 +387,11 @@ } hdr = &index->map->hdr; + i_debug("mail_index_sync_commit begin: " + "seq=%u head_offset=%u tail_offset=%u " + "(head seq=%u offset=%"PRIuUOFF_T")", + hdr->log_file_seq, hdr->log_file_head_offset, + hdr->log_file_tail_offset, seq, offset); if (hdr->log_file_tail_offset > hdr->log_file_head_offset || hdr->log_file_seq > seq || (hdr->log_file_seq == seq && hdr->log_file_tail_offset > offset)) { @@ -677,6 +686,8 @@ *_ctx = NULL; + i_debug("mail_index_sync_commit end"); + ctx->index->syncing = FALSE; mail_transaction_log_sync_unlock(ctx->index->log); @@ -769,6 +780,7 @@ { if ((*ctx)->ext_trans != NULL) mail_index_transaction_rollback(&(*ctx)->ext_trans); + i_debug("mail_index_sync_rollback"); mail_index_sync_end(ctx); } diff -r 96c8632775df src/lib-index/mail-index-transaction.c --- a/src/lib-index/mail-index-transaction.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-index-transaction.c Mon May 04 16:35:01 2009 -0400 @@ -755,6 +755,7 @@ void mail_index_expunge(struct mail_index_transaction *t, uint32_t seq) { i_assert(seq > 0); + i_debug("expunge: seq=%u", seq); if (seq >= t->first_new_seq) { /* we can handle only the last append. otherwise we'd have to renumber sequences and that gets tricky. for now this is diff -r 96c8632775df src/lib-index/mail-transaction-log-append.c --- a/src/lib-index/mail-transaction-log-append.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-transaction-log-append.c Mon May 04 16:35:01 2009 -0400 @@ -657,6 +657,10 @@ } buffer_free(&ctx.output); + i_debug("transaction: seq=%u: %llu .. %llu (ext %d)", + file->hdr.file_seq, append_offset, file->sync_offset, + (t->flags & MAIL_INDEX_TRANSACTION_FLAG_EXTERNAL) != 0); + if ((t->flags & MAIL_INDEX_TRANSACTION_FLAG_HIDE) != 0) { /* mark the area covered by this transaction hidden */ mail_index_view_add_hidden_transaction(view, file->hdr.file_seq, diff -r 96c8632775df src/lib-index/mail-transaction-log-file.c --- a/src/lib-index/mail-transaction-log-file.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-transaction-log-file.c Mon May 04 16:35:01 2009 -0400 @@ -42,6 +42,7 @@ t_strdup_vprintf(fmt, va), file->sync_offset); } T_END; va_end(va); + sleep(3600); } struct mail_transaction_log_file * diff -r 96c8632775df src/lib-index/mail-transaction-log-private.h --- a/src/lib-index/mail-transaction-log-private.h Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-transaction-log-private.h Mon May 04 16:35:01 2009 -0400 @@ -14,7 +14,7 @@ /* Rotate when log is older than ROTATE_TIME and larger than MIN_SIZE */ #define MAIL_TRANSACTION_LOG_ROTATE_MIN_SIZE (1024*32) /* If log is larger than MAX_SIZE, rotate regardless of the time */ -#define MAIL_TRANSACTION_LOG_ROTATE_MAX_SIZE (1024*1024) +#define MAIL_TRANSACTION_LOG_ROTATE_MAX_SIZE (1024*64) #define MAIL_TRANSACTION_LOG_ROTATE_TIME (60*5) /* Delete .log.2 files older than this many seconds */ diff -r 96c8632775df src/lib-index/mail-transaction-log-view.c --- a/src/lib-index/mail-transaction-log-view.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-index/mail-transaction-log-view.c Mon May 04 16:35:01 2009 -0400 @@ -293,6 +293,10 @@ view->max_file_offset = I_MIN(max_file_offset, view->head->sync_offset); view->broken = FALSE; + i_debug("view: %u,%llu .. %u,%llu", + view->min_file_seq, view->min_file_offset, + view->max_file_seq, view->max_file_offset); + i_assert(view->cur_offset <= view->cur->sync_offset); return 1; } diff -r 96c8632775df src/lib-storage/index/maildir/maildir-save.c --- a/src/lib-storage/index/maildir/maildir-save.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-storage/index/maildir/maildir-save.c Mon May 04 16:35:01 2009 -0400 @@ -681,6 +681,7 @@ /* assign the UIDs if we happen to get a lock */ sync_flags |= MAILDIR_UIDLIST_SYNC_TRYLOCK; } + i_debug("maildir_transaction_save_commit_pre"); ret = maildir_uidlist_sync_init(ctx->mbox->uidlist, sync_flags, &ctx->uidlist_sync_ctx); if (ret <= 0 && @@ -754,6 +755,7 @@ ret = maildir_uidlist_sync_next(ctx->uidlist_sync_ctx, dest, flags); i_assert(ret > 0); + i_debug("save pre: sync: %s ret=%d", dest, ret); } T_END; } @@ -797,11 +799,13 @@ maildir_transaction_save_rollback(ctx); return -1; } + i_debug("/maildir_transaction_save_commit_pre"); return ret; } void maildir_transaction_save_commit_post(struct maildir_save_context *ctx) { + i_debug("maildir_transaction_save_commit_post"); ctx->ctx.transaction = NULL; /* transaction is already freed */ if (ctx->locked) diff -r 96c8632775df src/lib-storage/index/maildir/maildir-sync-index.c --- a/src/lib-storage/index/maildir/maildir-sync-index.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-storage/index/maildir/maildir-sync-index.c Mon May 04 16:35:01 2009 -0400 @@ -14,6 +14,33 @@ #include #include +#include +#include +#include +#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); +} + struct maildir_index_sync_context { struct maildir_mailbox *mbox; struct maildir_sync_context *maildir_sync_ctx; @@ -43,8 +70,10 @@ struct maildir_index_sync_context *ctx) { struct mailbox *box = &mbox->ibox.box; + int ret = unlink(path); - if (unlink(path) == 0) { + i_debug("maildir_expunge: %s -> %d", path, ret); + if (ret == 0) { if (box->v.sync_notify != NULL) { box->v.sync_notify(box, ctx->uid, MAILBOX_SYNC_TYPE_EXPUNGE); @@ -390,6 +419,8 @@ i_assert(!mbox->syncing_commit); i_assert(maildir_uidlist_is_locked(mbox->uidlist)); + i_debug("maildir_sync_index: partial=%d", partial); + first_uid = 1; hdr = mail_index_get_header(view); uid_validity = maildir_uidlist_get_uid_validity(mbox->uidlist); @@ -411,6 +442,11 @@ } hdr_next_uid = hdr->next_uid; + for (seq = 1; seq <= hdr->messages_count; seq++) { + mail_index_lookup_uid(view, seq, &uid); + i_debug("index: seq=%u : uid=%u", seq, uid); + } + mbox->syncing_commit = TRUE; seq = prev_uid = 0; first_recent_uid = I_MAX(hdr->first_recent_uid, 1); t_array_init(&ctx->keywords, MAILDIR_MAX_KEYWORDS); @@ -431,8 +467,11 @@ ctx->seq = ++seq; ctx->uid = uid; + i_debug("seq=%u uid=%u name=%s flags=%x", seq, uid, filename, uflags); if (seq > hdr->messages_count) { + i_debug(" - idx new: %s", filename); if (uid < hdr_next_uid) { + i_debug(" - idx new racing: %u < %u", uid, hdr->next_uid); maildir_handle_uid_insertion(ctx, uflags, filename, uid); seq--; @@ -467,11 +506,13 @@ rec = mail_index_lookup(view, seq); if (uid > rec->uid) { /* expunged */ + i_debug(" - idx expunged: uid=%u (%u > %u)", rec->uid, uid, rec->uid); mail_index_expunge(trans, seq); goto again; } if (uid < rec->uid) { + i_debug(" - idx racing: uid=%u (%u < %u)", rec->uid, uid, rec->uid); maildir_handle_uid_insertion(ctx, uflags, filename, uid); seq--; @@ -480,6 +521,7 @@ index_sync_changes_read(ctx->sync_changes, rec->uid, &expunged); if (expunged) { + i_debug("maildir_sync_index: expunge: %u", uid); if (maildir_file_do(mbox, ctx->uid, maildir_expunge, ctx) >= 0) { /* successful expunge */ @@ -586,6 +628,7 @@ offsetof(struct mail_index_header, first_recent_uid), &first_recent_uid, sizeof(first_recent_uid), FALSE); } + i_debug("/maildir_sync_index, full_rescan=%d", full_rescan); return ret < 0 ? -1 : (full_rescan ? 0 : 1); } diff -r 96c8632775df src/lib-storage/index/maildir/maildir-sync.c --- a/src/lib-storage/index/maildir/maildir-sync.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-storage/index/maildir/maildir-sync.c Mon May 04 16:35:01 2009 -0400 @@ -369,6 +369,7 @@ bool move_new, check_touch, dir_changed = FALSE; path = new_dir ? ctx->new_dir : ctx->cur_dir; + i_debug("scanning dir %s", path); for (i = 0;; i++) { dirp = opendir(path); if (dirp != NULL) @@ -472,6 +473,7 @@ ret = maildir_uidlist_sync_next(ctx->uidlist_sync_ctx, dp->d_name, flags); + i_debug("found: %s, move=%d, ret=%d", dp->d_name, move_new, ret); if (ret <= 0) { if (ret < 0) break; @@ -485,6 +487,7 @@ break; } } + i_debug("----"); if (errno != 0) { mail_storage_set_critical(storage, @@ -681,6 +684,8 @@ *lost_files_r = FALSE; + i_debug("maildir_sync_context: forced=%d", forced); + if (forced) new_changed = cur_changed = TRUE; else { @@ -834,9 +839,11 @@ int ret; T_BEGIN { + i_debug("maildir_storage_sync_force"); ctx = maildir_sync_context_new(mbox, MAILBOX_SYNC_FLAG_FAST); ret = maildir_sync_context(ctx, TRUE, &uid, &lost_files); maildir_sync_deinit(ctx); + i_debug("/maildir_storage_sync_force"); } T_END; if (uid != 0) { @@ -862,6 +869,7 @@ if (!box->opened) index_storage_mailbox_open(&mbox->ibox); + i_debug("maildir_storage_sync_init"); if (index_mailbox_want_full_sync(&mbox->ibox, flags)) { T_BEGIN { ctx = maildir_sync_context_new(mbox, flags); @@ -879,6 +887,8 @@ } } + i_debug("/maildir_storage_sync_init"); + return index_mailbox_sync_init(box, flags, ret < 0); } diff -r 96c8632775df src/lib-storage/index/maildir/maildir-uidlist.c --- a/src/lib-storage/index/maildir/maildir-uidlist.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-storage/index/maildir/maildir-uidlist.c Mon May 04 16:35:01 2009 -0400 @@ -179,6 +179,7 @@ uidlist->lock_count++; uidlist->locked_refresh = FALSE; + i_debug("uidlist locked"); if (refresh) { /* make sure we have the latest changes before changing anything */ @@ -219,6 +220,7 @@ if (--uidlist->lock_count > 0) return; + i_debug("uidlist unlocked"); uidlist->locked_refresh = FALSE; (void)file_dotlock_delete(&uidlist->dotlock); } @@ -429,6 +431,21 @@ return TRUE; } +static void recs_check(struct maildir_uidlist *uidlist) +{ + struct maildir_uidlist_rec *const *recs; + unsigned int i, count; + + recs = array_get(&uidlist->records, &count); + for (i = 1; i < count; i++) { + if (recs[i]->uid == (uint32_t)-1) + break; + i_assert(recs[i-1]->uid < recs[i]->uid); + } + for (; i < count; i++) + i_assert(recs[i]->uid == (uint32_t)-1); +} + static bool maildir_uidlist_next(struct maildir_uidlist *uidlist, const char *line) { @@ -496,6 +513,7 @@ uidlist->path, uidlist->read_line_count, line); return FALSE; } + i_debug("read: uid=%u %s", rec->uid, line); old_rec = hash_lookup(uidlist->files, line); if (old_rec == NULL) { @@ -512,6 +530,7 @@ we'll waste a bit of memory here by allocating the record twice, but that's not really a problem. */ + i_debug("read: conflict uid=%u", uid); rec->filename = old_rec->filename; hash_insert(uidlist->files, rec->filename, rec); uidlist->unsorted = TRUE; @@ -523,6 +542,7 @@ "%s (uid %u -> %u)", uidlist->path, uidlist->read_line_count, line, old_rec->uid, uid); + sleep(3600); /* Delete the old UID */ maildir_uidlist_records_array_delete(uidlist, old_rec); /* Replace the old record with this new one */ @@ -535,6 +555,7 @@ if (count > 0 && recs[count-1]->uid > uid) { /* we most likely have some records in the array that we saved ourself without refreshing uidlist */ + i_debug("read: unsorted"); uidlist->unsorted = TRUE; } @@ -636,6 +657,7 @@ recs = array_get_modifiable(&uidlist->records, &count); qsort(recs, count, sizeof(*recs), maildir_uid_cmp); + recs_check(uidlist); uidlist->unsorted = FALSE; } @@ -682,6 +704,17 @@ last_read_offset = uidlist->last_read_offset; uidlist->last_read_offset = 0; } + i_debug("refresh: last_read_offset=%u, last_seen_uid=%u", + (int)last_read_offset, uidlist->last_seen_uid); + { + struct maildir_uidlist_rec *const *recs; + unsigned int i, count; + recs = array_get(&uidlist->records, &count); + for (i = 0; i < count; i++) { + i_debug("existing: uid=%u %s", recs[i]->uid, recs[i]->filename); + } + i_debug("-"); + } if (fstat(fd, &st) < 0) { close_keep_errno(fd); @@ -759,6 +792,9 @@ uidlist->fd_size = st.st_size; uidlist->last_read_offset = input->v_offset; maildir_uidlist_update_hdr(uidlist, &st); + i_debug("refreshed: ino=%u size=%u last_read_offset=%u", + (int)st.st_ino, (int)st.st_size, + (int)uidlist->last_read_offset); } else if (!*retry_r) { /* I/O error */ if (input->stream_errno == ESTALE && try_retry) @@ -838,6 +874,7 @@ return 1; } else { /* unchanged */ + i_debug("has_changed: no, ino=%u size=%u", (int)st.st_ino, (int)st.st_size); return 0; } } @@ -851,13 +888,18 @@ if (uidlist->fd != -1) { ret = maildir_uidlist_has_changed(uidlist, &recreated); if (ret <= 0) { + i_debug("refresh: uidlist not changed (%d)", ret); if (UIDLIST_IS_LOCKED(uidlist)) uidlist->locked_refresh = TRUE; return ret; } - if (recreated) + if (recreated) { + i_debug("refresh: uidlist recreated"); maildir_uidlist_close(uidlist); + } + } else { + i_debug("refresh: uidlist not opened yet"); } for (i = 0; ; i++) { @@ -874,6 +916,7 @@ if (UIDLIST_IS_LOCKED(uidlist)) uidlist->locked_refresh = TRUE; } + i_debug("refresh: ret=%d", ret); return ret; } @@ -1156,6 +1199,7 @@ p += len + 1; } } + i_debug("uidlist write: uid=%u %s", rec->uid, rec->filename); str_printfa(str, " :%s\n", rec->filename); o_stream_send(output, str_data(str), str_len(str)); } @@ -1194,6 +1238,7 @@ i_assert(uidlist->initial_read); + i_debug("uidlist rewrite"); control_dir = mailbox_list_get_path(box->storage->list, box->name, MAILBOX_LIST_PATH_TYPE_CONTROL); temp_path = t_strconcat(control_dir, @@ -1260,6 +1305,7 @@ uidlist->last_read_offset = st.st_size; uidlist->recreate = FALSE; maildir_uidlist_update_hdr(uidlist, &st); + i_debug("rewrite: ino=%u size=%u", (int)st.st_ino, (int)st.st_size); } if (ret < 0) (void)close(fd); @@ -1350,6 +1396,7 @@ return -1; } + i_debug("uidlist appending"); if (maildir_uidlist_write_fd(uidlist, uidlist->fd, uidlist->path, ctx->first_unwritten_pos, &file_size) < 0) return -1; @@ -1363,9 +1410,13 @@ i_warning("%s: file size changed unexpectedly after write", uidlist->path); } else if (uidlist->locked_refresh) { + i_debug("post-append: updated size=%lld", st.st_size); uidlist->fd_size = st.st_size; uidlist->last_read_offset = st.st_size; maildir_uidlist_update_hdr(uidlist, &st); + } else { + i_debug("post-append: not updated, size=%lld (keep: size=%u last_read_offset=%u)", + st.st_size, (int)uidlist->fd_size, (int)uidlist->last_read_offset); } return 0; } @@ -1455,6 +1506,7 @@ /* doesn't exist in uidlist */ if (!ctx->locked) { /* we can't add it, so just ignore it */ + i_debug("sync_next_partial: uidlist not locked, ignoring %s", filename); return; } if (ctx->first_nouid_pos == (unsigned int)-1) @@ -1473,7 +1525,11 @@ struct maildir_uidlist_rec, 1); rec->uid = (uint32_t)-1; array_append(&uidlist->records, &rec, 1); + recs_check(uidlist); uidlist->change_counter++; + i_debug("sync_next_partial: uidlist assigning new uid %s", filename); + } else { + i_debug("sync_next_partial: uidlist exists uid=%u %s", rec->uid, filename); } rec->flags = (rec->flags | flags) & ~MAILDIR_UIDLIST_REC_FLAG_NONSYNCED; @@ -1531,12 +1587,14 @@ if ((rec->flags & (MAILDIR_UIDLIST_REC_FLAG_NEW_DIR | MAILDIR_UIDLIST_REC_FLAG_MOVED)) == 0) { /* possibly duplicate */ + i_debug("sync_next: possible duplicate uid=%u %s", rec->uid, filename); return 0; } /* probably was in new/ and now we're seeing it in cur/. remove new/moved flags so if this happens again we'll know to check for duplicates. */ + i_debug("sync_next: moved to cur? uid=%u %s", rec->uid, filename); rec->flags &= ~(MAILDIR_UIDLIST_REC_FLAG_NEW_DIR | MAILDIR_UIDLIST_REC_FLAG_MOVED); } else { @@ -1549,7 +1607,9 @@ *rec = *old_rec; rec->extensions = ext_dup(ctx->record_pool, rec->extensions); + i_debug("sync_next: keeping uid=%u %s", rec->uid, filename); } else { + i_debug("sync_next: new file %s", filename); rec->uid = (uint32_t)-1; ctx->new_files_count++; ctx->changed = TRUE; @@ -1579,6 +1639,7 @@ i_assert(rec != NULL); i_assert(rec->uid != (uint32_t)-1); + i_debug("sync_remove: uid=%u %s", rec->uid, filename); hash_remove(ctx->uidlist->files, filename); idx = maildir_uidlist_records_array_delete(ctx->uidlist, rec); @@ -1652,6 +1713,8 @@ sizeof(*recs), maildir_time_cmp); for (dest = ctx->first_nouid_pos; dest < count; dest++) { + i_debug("uidlist assign uid: %s -> uid=%u", + recs[dest]->filename, ctx->uidlist->next_uid); i_assert(recs[dest]->uid == (uint32_t)-1); recs[dest]->uid = ctx->uidlist->next_uid++; recs[dest]->flags &= ~MAILDIR_UIDLIST_REC_FLAG_MOVED; @@ -1680,6 +1743,18 @@ uidlist->records = ctx->records; ctx->records.arr.buffer = NULL; + { + struct maildir_uidlist_rec *const *recs; + unsigned int i, count; + + i_debug("swapping to:"); + recs = array_get(&uidlist->records, &count); + for (i = 0; i < count; i++) { + i_debug("uid=%u %s", recs[i]->uid, recs[i]->filename); + } + i_debug("-"); + } + hash_destroy(&uidlist->files); uidlist->files = ctx->files; ctx->files = NULL; @@ -1699,6 +1774,9 @@ void maildir_uidlist_sync_finish(struct maildir_uidlist_sync_ctx *ctx) { + i_debug("sync finish, partial=%d changed=%d locked=%d failed=%d new_count=%u", + ctx->partial, ctx->changed, ctx->locked, ctx->failed, ctx->new_files_count); + if (!ctx->partial) { if (!ctx->failed) maildir_uidlist_swap(ctx); diff -r 96c8632775df src/lib-storage/index/maildir/maildir-util.c --- a/src/lib-storage/index/maildir/maildir-util.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib-storage/index/maildir/maildir-util.c Mon May 04 16:35:01 2009 -0400 @@ -24,8 +24,10 @@ int ret; ret = maildir_uidlist_lookup(mbox->uidlist, uid, &flags, &fname); - if (ret <= 0) + if (ret <= 0) { + i_debug("maildir_file_do_try: %u not found", uid); return ret == 0 ? -2 : -1; + } if ((flags & MAILDIR_UIDLIST_REC_FLAG_NEW_DIR) != 0) { /* probably in new/ dir */ diff -r 96c8632775df src/lib/failures.c --- a/src/lib/failures.c Mon May 04 16:34:21 2009 -0400 +++ b/src/lib/failures.c Mon May 04 16:35:01 2009 -0400 @@ -157,6 +157,7 @@ i_error("Raw backtrace: %s", backtrace); } + sleep(3600); if (type == LOG_TYPE_PANIC) abort(); else