From: Timo Sirainen Date: Tue, 1 Oct 2019 16:12:10 +0000 (+0300) Subject: lib-index: Log a debug message with reason whenever recreating dovecot.index X-Git-Tag: 2.3.11.2~517 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=61e2d33ea1d29f5418dae3b73090cbdf60e43e0a;p=thirdparty%2Fdovecot%2Fcore.git lib-index: Log a debug message with reason whenever recreating dovecot.index --- diff --git a/src/lib-index/mail-index-fsck.c b/src/lib-index/mail-index-fsck.c index a8157c241b..9147eebc2c 100644 --- a/src/lib-index/mail-index-fsck.c +++ b/src/lib-index/mail-index-fsck.c @@ -472,7 +472,7 @@ int mail_index_fsck(struct mail_index *index) mail_index_fsck_map(index, map); } T_END; - mail_index_write(index, FALSE); + mail_index_write(index, FALSE, "fscking"); if (!orig_locked) mail_transaction_log_sync_unlock(index->log, "fscking"); diff --git a/src/lib-index/mail-index-private.h b/src/lib-index/mail-index-private.h index dfe29297a0..67e63d2a7f 100644 --- a/src/lib-index/mail-index-private.h +++ b/src/lib-index/mail-index-private.h @@ -249,7 +249,8 @@ void mail_index_close_file(struct mail_index *index); int mail_index_reopen_if_changed(struct mail_index *index, const char **reason_r); /* Update/rewrite the main index file from index->map */ -void mail_index_write(struct mail_index *index, bool want_rotate); +void mail_index_write(struct mail_index *index, bool want_rotate, + const char *reason); void mail_index_flush_read_cache(struct mail_index *index, const char *path, int fd, bool locked); diff --git a/src/lib-index/mail-index-sync.c b/src/lib-index/mail-index-sync.c index a8237bd27f..d90fcbcc74 100644 --- a/src/lib-index/mail-index-sync.c +++ b/src/lib-index/mail-index-sync.c @@ -830,7 +830,7 @@ mail_index_sync_update_mailbox_offset(struct mail_index_sync_ctx *ctx) } } -static bool mail_index_sync_want_index_write(struct mail_index *index) +static bool mail_index_sync_want_index_write(struct mail_index *index, const char **reason_r) { uint32_t log_diff; @@ -839,18 +839,35 @@ static bool mail_index_sync_want_index_write(struct mail_index *index) /* dovecot.index points to an old .log file. we were supposed to rewrite the dovecot.index when rotating the log, so we shouldn't usually get here. */ + *reason_r = "points to old .log file"; return TRUE; } log_diff = index->map->hdr.log_file_tail_offset - index->last_read_log_file_tail_offset; - if (log_diff > index->optimization_set.index.rewrite_max_log_bytes || - (index->index_min_write && - log_diff > index->optimization_set.index.rewrite_min_log_bytes)) + if (log_diff > index->optimization_set.index.rewrite_max_log_bytes) { + *reason_r = t_strdup_printf( + ".log read %u..%u > rewrite_max_log_bytes %"PRIuUOFF_T, + index->map->hdr.log_file_tail_offset, + index->last_read_log_file_tail_offset, + index->optimization_set.index.rewrite_max_log_bytes); return TRUE; + } + if (index->index_min_write && + log_diff > index->optimization_set.index.rewrite_min_log_bytes) { + *reason_r = t_strdup_printf( + ".log read %u..%u > rewrite_min_log_bytes %"PRIuUOFF_T, + index->map->hdr.log_file_tail_offset, + index->last_read_log_file_tail_offset, + index->optimization_set.index.rewrite_min_log_bytes); + return TRUE; + } - if (index->need_recreate != NULL) + if (index->need_recreate != NULL) { + *reason_r = t_strdup_printf("Need to recreate index: %s", + index->need_recreate); return TRUE; + } return FALSE; } @@ -859,6 +876,7 @@ int mail_index_sync_commit(struct mail_index_sync_ctx **_ctx) struct mail_index_sync_ctx *ctx = *_ctx; struct mail_index *index = ctx->index; struct mail_cache_compress_lock *cache_lock = NULL; + const char *reason = NULL; uint32_t next_uid; bool want_rotate, index_undeleted, delete_index; int ret = 0, ret2; @@ -956,12 +974,12 @@ int mail_index_sync_commit(struct mail_index_sync_ctx **_ctx) However, it's still safe to do the rotation because external transactions don't require syncing. */ want_rotate = ctx->fully_synced && - mail_transaction_log_want_rotate(index->log); + mail_transaction_log_want_rotate(index->log, &reason); if (ret == 0 && - (want_rotate || mail_index_sync_want_index_write(index))) { + (want_rotate || mail_index_sync_want_index_write(index, &reason))) { i_free(index->need_recreate); index->index_min_write = FALSE; - mail_index_write(index, want_rotate); + mail_index_write(index, want_rotate, reason); } mail_index_sync_end(_ctx); return ret; diff --git a/src/lib-index/mail-index-write.c b/src/lib-index/mail-index-write.c index 473c4e1805..791cf9f1ce 100644 --- a/src/lib-index/mail-index-write.c +++ b/src/lib-index/mail-index-write.c @@ -116,7 +116,8 @@ static int mail_index_recreate(struct mail_index *index) return ret; } -void mail_index_write(struct mail_index *index, bool want_rotate) +void mail_index_write(struct mail_index *index, bool want_rotate, + const char *reason) { struct mail_index_header *hdr = &index->map->hdr; @@ -152,6 +153,8 @@ void mail_index_write(struct mail_index *index, bool want_rotate) } if (!MAIL_INDEX_IS_IN_MEMORY(index)) { + e_debug(index->event, "Recreating %s because: %s", + index->filepath, reason); if (mail_index_recreate(index) < 0) { (void)mail_index_move_to_memory(index); return; diff --git a/src/lib-index/mail-transaction-log-private.h b/src/lib-index/mail-transaction-log-private.h index 79e800fda4..27202bd033 100644 --- a/src/lib-index/mail-transaction-log-private.h +++ b/src/lib-index/mail-transaction-log-private.h @@ -131,7 +131,8 @@ int mail_transaction_log_file_move_to_memory(struct mail_transaction_log_file *f void mail_transaction_logs_clean(struct mail_transaction_log *log); -bool mail_transaction_log_want_rotate(struct mail_transaction_log *log); +bool mail_transaction_log_want_rotate(struct mail_transaction_log *log, + const char **reason_r); int mail_transaction_log_rotate(struct mail_transaction_log *log, bool reset); int mail_transaction_log_lock_head(struct mail_transaction_log *log, const char *lock_reason); diff --git a/src/lib-index/mail-transaction-log.c b/src/lib-index/mail-transaction-log.c index 1133a83bb0..87c861f9f9 100644 --- a/src/lib-index/mail-transaction-log.c +++ b/src/lib-index/mail-transaction-log.c @@ -231,22 +231,31 @@ void mail_transaction_logs_clean(struct mail_transaction_log *log) i_assert(log->head == NULL || log->files != NULL); } -bool mail_transaction_log_want_rotate(struct mail_transaction_log *log) +bool mail_transaction_log_want_rotate(struct mail_transaction_log *log, + const char **reason_r) { struct mail_transaction_log_file *file = log->head; - if (file->need_rotate) + if (file->need_rotate != NULL) { + *reason_r = t_strdup(file->need_rotate); return TRUE; + } if (file->hdr.major_version < MAIL_TRANSACTION_LOG_MAJOR_VERSION || (file->hdr.major_version == MAIL_TRANSACTION_LOG_MAJOR_VERSION && file->hdr.minor_version < MAIL_TRANSACTION_LOG_MINOR_VERSION)) { /* upgrade immediately to a new log file format */ + *reason_r = t_strdup_printf( + ".log file format version %u.%u is too old", + file->hdr.major_version, file->hdr.minor_version); return TRUE; } if (file->sync_offset > log->index->optimization_set.log.max_size) { /* file is too large, definitely rotate */ + *reason_r = t_strdup_printf( + ".log file size %"PRIuUOFF_T" > max_size %"PRIuUOFF_T, + file->sync_offset, log->index->optimization_set.log.max_size); return TRUE; } if (file->sync_offset < log->index->optimization_set.log.min_size) { @@ -254,8 +263,15 @@ bool mail_transaction_log_want_rotate(struct mail_transaction_log *log) return FALSE; } /* rotate if the timestamp is old enough */ - return file->hdr.create_stamp < - ioloop_time - log->index->optimization_set.log.min_age_secs; + if (file->hdr.create_stamp < + ioloop_time - log->index->optimization_set.log.min_age_secs) { + *reason_r = t_strdup_printf( + ".log create_stamp %u is older than %u secs", + file->hdr.create_stamp, + log->index->optimization_set.log.min_age_secs); + return TRUE; + } + return FALSE; } int mail_transaction_log_rotate(struct mail_transaction_log *log, bool reset)