Index: src/lib/failures.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib/failures.c,v retrieving revision 1.27.2.5 diff -u -r1.27.2.5 failures.c --- src/lib/failures.c 19 Jan 2007 18:25:51 -0000 1.27.2.5 +++ src/lib/failures.c 22 Jan 2007 16:21:54 -0000 @@ -12,6 +12,8 @@ #include #include +#define abort() { char *x = 0; *x = 0; } + static void default_panic_handler(const char *format, va_list args) __attr_noreturn__ __attr_format__(1, 0); static void default_fatal_handler(int status, const char *format, va_list args) @@ -231,6 +233,27 @@ va_end(args); } +#include +#include +void i_debug(const char *format, ...) +{ + FILE *f; + va_list args; + struct timeval tv; + + gettimeofday(&tv, NULL); + + va_start(args, format); + t_push(); + f = fopen(t_strdup_printf("/tmp/dovecot.%d", getpid()), "a+"); + fprintf(f, "%10u.%06u PID=%s %s\n", + (unsigned)tv.tv_sec, (unsigned)tv.tv_usec, + dec2str(getpid()), t_strdup_vprintf(format, args)); + fclose(f); + t_pop(); + va_end(args); +} + void i_set_panic_handler(failure_callback_t *callback __attr_noreturn__) { if (callback == NULL) Index: src/lib/failures.h =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib/failures.h,v retrieving revision 1.9.2.1 diff -u -r1.9.2.1 failures.h --- src/lib/failures.h 1 Nov 2006 18:50:14 -0000 1.9.2.1 +++ src/lib/failures.h 22 Jan 2007 16:21:54 -0000 @@ -22,6 +22,7 @@ void i_error(const char *format, ...) __attr_format__(1, 2); void i_warning(const char *format, ...) __attr_format__(1, 2); void i_info(const char *format, ...) __attr_format__(1, 2); +void i_debug(const char *format, ...) __attr_format__(1, 2); void i_fatal_status(int status, const char *format, ...) __attr_format__(2, 3) __attr_noreturn__; Index: src/lib-index/mail-index-sync-update.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-index/mail-index-sync-update.c,v retrieving revision 1.96.2.8 diff -u -r1.96.2.8 mail-index-sync-update.c --- src/lib-index/mail-index-sync-update.c 17 Jan 2007 23:33:26 -0000 1.96.2.8 +++ src/lib-index/mail-index-sync-update.c 22 Jan 2007 16:21:54 -0000 @@ -151,6 +153,19 @@ hdr->first_deleted_uid_lowwater = rec->uid; } +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, struct mail_index_sync_map_ctx *ctx) { @@ -183,6 +198,10 @@ /* we want atomic rename()ing */ map->write_atomic = TRUE; + i_debug("%s: sync_expunge", sync_type(ctx)); + for (seq = e->uid1; seq <= e->uid2; seq++) + i_debug("%s: sync_expunge: %u", sync_type(ctx), seq); + if (mail_index_lookup_uid_range(view, e->uid1, e->uid2, &seq1, &seq2) < 0) return -1; @@ -218,6 +237,12 @@ } } + for (seq = seq1; seq <= seq2; seq++) { + rec = MAIL_INDEX_MAP_IDX(map, seq-1); + i_debug("%s: sync_expunge loop: %u", sync_type(ctx), rec->uid); + } + i_debug("%s: ---", sync_type(ctx)); + for (i = 0; i < expunge_handlers_count; i++) { eh = &expunge_handlers[i]; @@ -514,6 +539,9 @@ case MAIL_TRANSACTION_EXPUNGE|MAIL_TRANSACTION_EXPUNGE_PROT: { const struct mail_transaction_expunge *rec, *end; + i_debug("%s: expunge: external = %d", sync_type(ctx), + (hdr->type & MAIL_TRANSACTION_EXTERNAL) != 0); + end = CONST_PTR_OFFSET(data, hdr->size); for (rec = data; rec < end; rec++) { ret = sync_expunge(rec, ctx); Index: src/lib-index/mail-index-sync.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-index/mail-index-sync.c,v retrieving revision 1.72.2.3 diff -u -r1.72.2.3 mail-index-sync.c --- src/lib-index/mail-index-sync.c 12 Nov 2006 15:20:35 -0000 1.72.2.3 +++ src/lib-index/mail-index-sync.c 22 Jan 2007 16:21:54 -0000 @@ -206,6 +206,7 @@ } /* read all transactions from log into a transaction in memory */ + i_debug("read_and_sort"); while ((ret = mail_transaction_log_view_next(ctx->view->log_view, &ctx->hdr, &ctx->data, NULL)) > 0) { @@ -214,6 +215,7 @@ else mail_index_sync_add_transaction(ctx); } + 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. */ @@ -348,6 +350,8 @@ unsigned int lock_id = 0; bool seen_external; + i_debug("mail_index_sync_begin"); + if (mail_transaction_log_sync_lock(index->log, &seq, &offset) < 0) return -1; @@ -645,6 +649,8 @@ uoff_t offset; int ret = 0; + i_debug("mail_index_sync_commit begin"); + if (mail_transaction_log_view_is_corrupted(ctx->view->log_view)) ret = -1; @@ -686,11 +692,13 @@ } mail_index_sync_end(_ctx); + i_debug("mail_index_sync_commit end"); return ret; } void mail_index_sync_rollback(struct mail_index_sync_ctx **ctx) { + i_debug("mail_index_sync_rollback"); mail_index_sync_end(ctx); } Index: src/lib-index/mail-index-transaction.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-index/mail-index-transaction.c,v retrieving revision 1.76.2.2 diff -u -r1.76.2.2 mail-index-transaction.c --- src/lib-index/mail-index-transaction.c 22 Jan 2007 15:21:12 -0000 1.76.2.2 +++ src/lib-index/mail-index-transaction.c 22 Jan 2007 16:21:54 -0000 @@ -212,6 +212,13 @@ } *seq = rec->uid; } + if (array == &t->expunges) { + uint32_t x; + i_assert(seq[-2] <= seq[-1]); + for (x = seq[-2]; x <= seq[-1]; x++) + i_debug("transaction expunge: %u (ext=%d)", + x, t->external); + } } } @@ -468,6 +475,8 @@ { i_assert(seq > 0 && seq <= mail_index_view_get_messages_count(t->view)); + i_debug("expunge: seq=%u", seq); + t->log_updates = TRUE; /* expunges is a sorted array of {seq1, seq2, ..}, .. */ Index: src/lib-index/mail-transaction-log-append.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-index/mail-transaction-log-append.c,v retrieving revision 1.17.2.2 diff -u -r1.17.2.2 mail-transaction-log-append.c --- src/lib-index/mail-transaction-log-append.c 16 Jan 2007 21:58:48 -0000 1.17.2.2 +++ src/lib-index/mail-transaction-log-append.c 22 Jan 2007 16:21:54 -0000 @@ -494,6 +494,9 @@ } } + i_debug("transaction: seq=%u: %llu .. %llu (ext %d)", + file->hdr.file_seq, append_offset, file->sync_offset, + t->external); if (ret < 0) { if (array_is_created(&view->syncs_hidden)) { /* revert changes to log_syncs */ Index: src/lib-index/mail-transaction-log-view.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-index/mail-transaction-log-view.c,v retrieving revision 1.45.2.4 diff -u -r1.45.2.4 mail-transaction-log-view.c --- src/lib-index/mail-transaction-log-view.c 17 Jan 2007 16:17:38 -0000 1.45.2.4 +++ src/lib-index/mail-transaction-log-view.c 22 Jan 2007 16:21:54 -0000 @@ -230,6 +230,10 @@ i_assert(view->cur_offset <= view->cur->sync_offset); i_assert(view->cur->hdr.file_seq == min_file_seq); + + i_debug("view: %u,%llu .. %u,%llu", + view->min_file_seq, view->min_file_offset, + view->max_file_seq, view->max_file_offset); return 1; } Index: src/lib-storage/index/index-transaction.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/index-transaction.c,v retrieving revision 1.14 diff -u -r1.14 index-transaction.c --- src/lib-storage/index/index-transaction.c 14 Jan 2006 18:47:42 -0000 1.14 +++ src/lib-storage/index/index-transaction.c 22 Jan 2007 16:21:54 -0000 @@ -45,6 +45,7 @@ if (ret < 0) mail_storage_set_index_error(t->ibox); else { + i_debug("index_transaction_commit, seq=%u", seq); if (seq != 0) { t->ibox->commit_log_file_seq = seq; t->ibox->commit_log_file_offset = offset; Index: src/lib-storage/index/maildir/maildir-save.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-save.c,v retrieving revision 1.70.2.5 diff -u -r1.70.2.5 maildir-save.c --- src/lib-storage/index/maildir/maildir-save.c 22 Jan 2007 15:21:11 -0000 1.70.2.5 +++ src/lib-storage/index/maildir/maildir-save.c 22 Jan 2007 16:21:55 -0000 @@ -460,6 +460,8 @@ i_assert(ctx->output == NULL); i_assert(ctx->finished); + i_debug("maildir_transaction_save_commit_pre"); + if (maildir_uidlist_sync_init(ctx->mbox->uidlist, TRUE, &ctx->uidlist_sync_ctx) <= 0) { /* error or timeout - our transaction is broken */ @@ -510,6 +512,7 @@ if (ret == 0) { ret = maildir_uidlist_sync_next(ctx->uidlist_sync_ctx, dest, flags); + i_debug("save pre: sync: %s", dest); i_assert(ret != 0); ret = ret < 0 ? -1 : 0; } @@ -532,11 +535,14 @@ maildir_transaction_save_rollback(ctx); } + 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"); + /* uidlist locks the syncing. don't release it until save's transaction has been written to disk. */ (void)maildir_uidlist_sync_deinit(&ctx->uidlist_sync_ctx); Index: src/lib-storage/index/maildir/maildir-sync.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-sync.c,v retrieving revision 1.77.2.3 diff -u -r1.77.2.3 maildir-sync.c --- src/lib-storage/index/maildir/maildir-sync.c 7 Nov 2006 21:22:06 -0000 1.77.2.3 +++ src/lib-storage/index/maildir/maildir-sync.c 22 Jan 2007 16:21:55 -0000 @@ -383,7 +383,10 @@ static int maildir_expunge(struct maildir_mailbox *mbox, const char *path, void *context __attr_unused__) { - if (unlink(path) == 0) { + int ret = unlink(path); + + i_debug("maildir_expunge: %s -> %d", path, ret); + if (ret == 0) { mbox->dirty_cur_time = ioloop_time; return 1; } @@ -502,6 +505,7 @@ ctx->seq = seq; if (expunged) { + i_debug("maildir_sync_record: expunge: %u", uid); if (maildir_file_do(ctx->mbox, uid, maildir_expunge, ctx) < 0) return -1; @@ -545,6 +549,14 @@ if (sync_rec->type == MAIL_INDEX_SYNC_TYPE_APPEND) return 0; /* ignore */ + if (sync_rec->type == MAIL_INDEX_SYNC_TYPE_EXPUNGE) { + unsigned int uid; + + for (uid = sync_rec->uid1; uid <= sync_rec->uid2; uid++) + i_debug("maildir_sync_record: expunge UID %u", uid); + i_debug("---"); + } + /* convert to sequences to avoid looping through huge holes in UID range */ sync_copy = *sync_rec; @@ -580,10 +592,12 @@ struct mail_index_sync_rec sync_rec; int ret; + i_debug("maildir_sync_index_records"); ret = mail_index_sync_next(ctx->sync_ctx, &sync_rec); if (ret <= 0) return ret; + i_debug("committing changes"); ARRAY_CREATE(&ctx->sync_recs, pool_datastack_create(), struct mail_index_sync_rec, 32); do { @@ -684,6 +698,7 @@ bool move_new; dir = new_dir ? ctx->new_dir : ctx->cur_dir; + i_debug("scanning dir %s", dir); dirp = opendir(dir); if (dirp == NULL) { mail_storage_set_critical(storage, @@ -710,6 +725,7 @@ ctx->mbox->last_new_mtime = 0; else ctx->mbox->dirty_cur_time = ioloop_time; + i_debug("found %s: new file, no locking", dp->d_name); continue; } if (ret < 0) @@ -754,6 +770,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; @@ -765,6 +782,7 @@ } } } + i_debug("----"); if (closedir(dirp) < 0) { mail_storage_set_critical(storage, @@ -890,6 +908,8 @@ uoff_t offset; int ret = failed ? -1 : 0; + i_debug("maildir_sync_index_finish"); + *_sync_ctx = NULL; if (sync_ctx->trans != NULL) { @@ -948,6 +968,8 @@ bool full_rescan = FALSE; i_assert(maildir_uidlist_is_locked(sync_ctx->mbox->uidlist)); + i_debug("maildir_sync_index, partial=%d, syncing_commit=%d", + partial, mbox->syncing_commit); hdr = mail_index_get_header(view); uid_validity = maildir_uidlist_get_uid_validity(mbox->uidlist); @@ -966,6 +988,12 @@ sync_ctx->trans = trans = mail_index_transaction_begin(sync_ctx->view, FALSE, TRUE); + for (seq = 1; seq <= hdr->messages_count; seq++) { + if (mail_index_lookup_uid(view, seq, &uid) < 0) + return -1; + i_debug("index: %u = %u", seq, uid); + } + seq = 0; ARRAY_CREATE(&keywords, pool_datastack_create(), unsigned int, MAILDIR_MAX_KEYWORDS); @@ -990,8 +1018,12 @@ __again: seq++; + i_debug("seq %u uid %u name %s flags %x", seq, uid, filename, uflags); if (seq > hdr->messages_count) { + i_debug(" - new file: %s", filename); + seq--; if (uid < hdr->next_uid) { + i_debug(" - new racing: %u < %u", uid, hdr->next_uid); /* most likely a race condition: we read the maildir, then someone else expunged messages and committed changes to index. so, this @@ -1015,6 +1047,7 @@ "(%u < %u, file = %s)", mbox->path, uid, hdr->next_uid, filename); + abort(); mail_index_mark_corrupted( mbox->ibox.index); ret = -1; @@ -1024,8 +1057,6 @@ maildir_uidlist_add_flags(mbox->uidlist, filename, MAILDIR_UIDLIST_REC_FLAG_RACING); - - seq--; continue; } @@ -1052,6 +1083,7 @@ if (rec->uid < uid) { /* expunged */ + i_debug(" - expunged: %u < %u", rec->uid, uid); mail_index_expunge(trans, seq); goto __again; } @@ -1068,6 +1100,7 @@ seq--; continue; } + i_debug(" - racing: %u > %u", rec->uid, uid); if ((uflags & MAILDIR_UIDLIST_REC_FLAG_RACING) != 0) { mail_storage_set_critical( STORAGE(mbox->storage), @@ -1075,6 +1108,7 @@ "UID inserted in the middle of mailbox " "(%u > %u, file = %s)", mbox->path, rec->uid, uid, filename); + abort(); mail_index_mark_corrupted(mbox->ibox.index); ret = -1; break; @@ -1224,6 +1258,7 @@ &uid_validity, sizeof(uid_validity), TRUE); } + i_debug("/maildir_sync_index, full_rescan=%d", full_rescan); return ret < 0 ? -1 : (full_rescan ? 0 : 1); } @@ -1233,6 +1268,9 @@ bool new_changed, cur_changed, full_rescan = FALSE; int ret; + i_debug("maildir_sync_context: forced=%d, sync_last_commit=%d", + forced, sync_last_commit); + if (sync_last_commit) { new_changed = cur_changed = FALSE; } else if (!forced) { @@ -1355,9 +1393,12 @@ struct maildir_sync_context *ctx; int ret; + i_debug("maildir_storage_sync_force"); + ctx = maildir_sync_context_new(mbox); ret = maildir_sync_context(ctx, TRUE, FALSE); maildir_sync_deinit(ctx); + i_debug("/maildir_storage_sync_force"); return ret < 0 ? -1 : 0; } @@ -1366,6 +1407,8 @@ struct maildir_sync_context *ctx; int ret; + i_debug("maildir_sync_last_commit, log_file_seq=%u", + mbox->ibox.commit_log_file_seq); if (mbox->ibox.commit_log_file_seq == 0) return 0; @@ -1382,6 +1425,8 @@ struct maildir_sync_context *ctx; int ret = 0; + i_debug("maildir_storage_sync_init"); + if ((flags & MAILBOX_SYNC_FLAG_FAST) == 0 || mbox->ibox.sync_last_check + MAILBOX_FULL_SYNC_INTERVAL <= ioloop_time) { @@ -1400,6 +1445,8 @@ } } + i_debug("/maildir_storage_sync_init"); + return index_mailbox_sync_init(box, flags, ret < 0); } Index: src/lib-storage/index/maildir/maildir-uidlist.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-uidlist.c,v retrieving revision 1.51.2.5 diff -u -r1.51.2.5 maildir-uidlist.c --- src/lib-storage/index/maildir/maildir-uidlist.c 18 Jan 2007 17:20:45 -0000 1.51.2.5 +++ src/lib-storage/index/maildir/maildir-uidlist.c 22 Jan 2007 16:21:55 -0000 @@ -557,6 +557,8 @@ } } + i_debug("rewriting uidlist, delayed=%d", uidlist->delayed_rewrite); + uidlist->version = 1; if (uidlist->uid_validity == 0) { @@ -736,6 +738,8 @@ buffer_append(uidlist->record_buf, &rec, sizeof(rec)); } + i_debug("sync next partial: %s -> uid %u", filename, rec->uid); + if ((flags & MAILDIR_UIDLIST_REC_FLAG_RECENT) != 0 && rec->uid != (uint32_t)-1) maildir_uidlist_mark_recent(uidlist, rec->uid); @@ -873,6 +877,9 @@ qsort(rec_p + first_new_pos, size - first_new_pos, sizeof(*rec_p), maildir_time_cmp); for (dest = first_new_pos; dest < size; dest++) { + i_debug("assign uid: %s -> uid %u", + rec_p[dest]->filename, uidlist->next_uid); + i_assert(rec_p[dest]->uid == (uint32_t)-1); rec_p[dest]->uid = uidlist->next_uid++; rec_p[dest]->flags &= ~MAILDIR_UIDLIST_REC_FLAG_MOVED; Index: src/lib-storage/index/maildir/maildir-util.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-util.c,v retrieving revision 1.14.2.4 diff -u -r1.14.2.4 maildir-util.c --- src/lib-storage/index/maildir/maildir-util.c 18 Jan 2007 17:20:46 -0000 1.14.2.4 +++ src/lib-storage/index/maildir/maildir-util.c 22 Jan 2007 16:21:55 -0000 @@ -22,8 +22,10 @@ int ret; fname = maildir_uidlist_lookup(mbox->uidlist, uid, &flags); - if (fname == NULL) + if (fname == NULL) { + i_debug("maildir_file_do_try: %u not found", uid); return -2; /* expunged */ + } t_push(); if ((flags & MAILDIR_UIDLIST_REC_FLAG_NEW_DIR) != 0) {