? src/diff ? src/auth/run.sh ? src/deliver/DEADJOE ? src/imap/INBOX ? src/imap/diff ? src/imap/gmon.out ? src/imap/log ? src/imap/log2 ? src/imap/old ? src/imap/prof ? src/imap/real ? src/imap/ref.sh ? src/imap-login/diff ? src/imap-login/gmon.out ? src/imap-login/log ? src/lib/debug.diff ? src/lib/diff ? src/lib/inotify.h ? src/lib/mempool-accounting.diff ? src/lib/nohup.out ? src/lib-dict/diff ? src/lib-index/diff ? src/lib-index/idxview ? src/lib-index/idxview.c ? src/lib-index/logview ? src/lib-index/logview.c ? src/lib-index/m ? src/lib-index/old ? src/lib-mail/diff ? src/lib-mail/diff2 ? src/lib-sql/diff ? src/lib-storage/index/asd ? src/lib-storage/index/dbox/dbox-debug.diff ? src/lib-storage/index/dbox/dbox-info ? src/lib-storage/index/dbox/dbox-info.c ? src/lib-storage/index/dbox/debug.diff ? src/lib-storage/index/dbox/diff ? src/lib-storage/index/dbox/old ? src/lib-storage/index/maildir/diff ? src/lib-storage/index/mbox/diff ? src/lib-storage/index/mbox/mbox-lock.c2 ? src/lib-storage/index/mbox/mbox-min-index-size.diff ? src/login-common/log ? src/master/diff ? src/master/log ? src/plugins/mail-sql ? src/plugins/mail-sql.tar.gz ? src/plugins/fts-squat/diff ? src/plugins/fts-squat/old ? src/plugins/fts-squat/squat-dump ? src/plugins/fts-squat/squat-dump.c ? src/plugins/fts-squat/vgcore.17402 ? src/plugins/quota/new ? src/pop3/log Index: src/lib/failures.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib/failures.c,v retrieving revision 1.33 diff -u -r1.33 failures.c --- src/lib/failures.c 19 Jan 2007 18:25:53 -0000 1.33 +++ src/lib/failures.c 6 Feb 2007 16:01:50 -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) @@ -236,6 +238,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.10 diff -u -r1.10 failures.h --- src/lib/failures.h 1 Nov 2006 18:47:37 -0000 1.10 +++ src/lib/failures.h 6 Feb 2007 16:01:50 -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.111 diff -u -r1.111 mail-index-sync-update.c --- src/lib-index/mail-index-sync-update.c 6 Feb 2007 16:01:23 -0000 1.111 +++ src/lib-index/mail-index-sync-update.c 6 Feb 2007 16:01:50 -0000 @@ -209,6 +209,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) { @@ -241,6 +254,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; @@ -276,6 +293,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]; @@ -577,6 +600,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); @@ -766,6 +792,9 @@ int ret; bool had_dirty, skipped, check_ext_offsets; + i_debug("mail_index_sync_update_index: sync_only_external=%d", + sync_only_external); + mail_index_sync_map_init(&sync_map_ctx, view, MAIL_INDEX_SYNC_HANDLER_FILE); sync_map_ctx.sync_only_external = sync_only_external; @@ -868,6 +897,11 @@ i_assert(map->records_count == map->hdr.messages_count); i_assert(map->hdr_copy_buf->used <= map->hdr.header_size); + i_debug("mail_index_sync_update_index: finished " + "seq=%u int_offset=%u ext_offset=%u", + map->hdr.log_file_seq, map->hdr.log_file_int_offset, + map->hdr.log_file_ext_offset); + if (first_append_uid != 0) mail_index_update_day_headers(&map->hdr, first_append_uid); 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.82 diff -u -r1.82 mail-index-sync.c --- src/lib-index/mail-index-sync.c 23 Jan 2007 16:30:54 -0000 1.82 +++ src/lib-index/mail-index-sync.c 6 Feb 2007 16:01:50 -0000 @@ -202,6 +202,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) { @@ -210,6 +211,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. */ @@ -318,6 +320,8 @@ write all external transactions to index. */ mail_transaction_log_view_get_prev_pos(ctx->view->log_view, &seq, &offset); + i_debug("mail_index_sync_commit_external: " + "found at seq=%u offset=%"PRIuUOFF_T, seq, offset); if (mail_index_sync_set_log_view(ctx->view, seq, offset) < 0) return -1; if (mail_index_sync_update_index(ctx, TRUE) < 0) @@ -344,6 +348,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; @@ -652,6 +658,11 @@ mail_transaction_log_get_head(index->log, &seq, &offset); hdr = index->hdr; + i_debug("mail_index_sync_commit begin: " + "seq=%u int_offset=%u ext_offset=%u " + "(head seq=%u offset=%"PRIuUOFF_T")", + hdr->log_file_seq, hdr->log_file_int_offset, + hdr->log_file_ext_offset, seq, offset); if (ret == 0 && (hdr->log_file_seq != seq || hdr->log_file_int_offset != offset || hdr->log_file_ext_offset != offset || @@ -684,11 +695,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.85 diff -u -r1.85 mail-index-transaction.c --- src/lib-index/mail-index-transaction.c 22 Jan 2007 15:21:16 -0000 1.85 +++ src/lib-index/mail-index-transaction.c 6 Feb 2007 16:01:51 -0000 @@ -189,6 +189,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); + } } } @@ -450,6 +457,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.20 diff -u -r1.20 mail-transaction-log-append.c --- src/lib-index/mail-transaction-log-append.c 16 Jan 2007 21:58:52 -0000 1.20 +++ src/lib-index/mail-transaction-log-append.c 6 Feb 2007 16:01:51 -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.51 diff -u -r1.51 mail-transaction-log-view.c --- src/lib-index/mail-transaction-log-view.c 26 Jan 2007 13:58:52 -0000 1.51 +++ src/lib-index/mail-transaction-log-view.c 6 Feb 2007 16:01:51 -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/maildir/maildir-save.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-save.c,v retrieving revision 1.79 diff -u -r1.79 maildir-save.c --- src/lib-storage/index/maildir/maildir-save.c 22 Jan 2007 15:21:15 -0000 1.79 +++ src/lib-storage/index/maildir/maildir-save.c 6 Feb 2007 16:01:51 -0000 @@ -489,6 +489,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 */ @@ -539,6 +541,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; } @@ -561,11 +564,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.88 diff -u -r1.88 maildir-sync.c --- src/lib-storage/index/maildir/maildir-sync.c 25 Jan 2007 16:01:37 -0000 1.88 +++ src/lib-storage/index/maildir/maildir-sync.c 6 Feb 2007 16:01:51 -0000 @@ -381,7 +381,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; } @@ -501,6 +504,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; @@ -544,6 +548,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; @@ -690,6 +702,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, @@ -716,6 +729,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) @@ -760,6 +774,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; @@ -771,6 +786,7 @@ } } } + i_debug("----"); if (closedir(dirp) < 0) { mail_storage_set_critical(storage, @@ -917,6 +933,8 @@ uoff_t offset; int ret = failed ? -1 : 0; + i_debug("maildir_sync_index_finish"); + *_sync_ctx = NULL; if (sync_ctx->trans != NULL) { @@ -979,6 +997,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); @@ -997,6 +1017,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; t_array_init(&keywords, MAILDIR_MAX_KEYWORDS); t_array_init(&idx_keywords, MAILDIR_MAX_KEYWORDS); @@ -1019,8 +1045,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 @@ -1044,6 +1074,7 @@ "(%u < %u, file = %s)", mbox->path, uid, hdr->next_uid, filename); + abort(); mail_index_mark_corrupted( mbox->ibox.index); ret = -1; @@ -1053,8 +1084,6 @@ maildir_uidlist_add_flags(mbox->uidlist, filename, MAILDIR_UIDLIST_REC_FLAG_RACING); - - seq--; continue; } @@ -1082,6 +1111,7 @@ if (rec->uid < uid) { /* expunged */ + i_debug(" - expunged: %u < %u", rec->uid, uid); mail_index_expunge(trans, seq); goto __again; } @@ -1098,6 +1128,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), @@ -1105,6 +1136,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; @@ -1249,6 +1281,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); } @@ -1258,6 +1291,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) { @@ -1380,9 +1416,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; } @@ -1391,6 +1430,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; @@ -1410,6 +1451,8 @@ if (!box->opened) index_storage_mailbox_open(&mbox->ibox); + i_debug("maildir_storage_sync_init"); + if ((flags & MAILBOX_SYNC_FLAG_FAST) == 0 || mbox->ibox.sync_last_check + MAILBOX_FULL_SYNC_INTERVAL <= ioloop_time) { @@ -1428,6 +1471,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.59 diff -u -r1.59 maildir-uidlist.c --- src/lib-storage/index/maildir/maildir-uidlist.c 23 Jan 2007 13:48:58 -0000 1.59 +++ src/lib-storage/index/maildir/maildir-uidlist.c 6 Feb 2007 16:01:51 -0000 @@ -556,6 +556,8 @@ } } + i_debug("rewriting uidlist, delayed=%d", uidlist->delayed_rewrite); + uidlist->version = 1; if (uidlist->uid_validity == 0) { @@ -737,6 +739,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); @@ -874,6 +878,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.21 diff -u -r1.21 maildir-util.c --- src/lib-storage/index/maildir/maildir-util.c 18 Jan 2007 17:20:50 -0000 1.21 +++ src/lib-storage/index/maildir/maildir-util.c 6 Feb 2007 16:01:51 -0000 @@ -23,8 +23,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) {