changeset 21087:3b909cd1264b

lib-index: Improve error messages when transaction log is unexpectedly lost
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Fri, 11 Nov 2016 17:00:39 +0200
parents 9e3dcad11d5f
children 617c400a8324
files src/lib-index/mail-index-map-read.c src/lib-index/mail-index-private.h src/lib-index/mail-index-sync-private.h src/lib-index/mail-index-sync-update.c src/lib-index/mail-index.c src/lib-index/mail-transaction-log-view.c
diffstat 6 files changed, 59 insertions(+), 17 deletions(-) [+]
line wrap: on
line diff
--- a/src/lib-index/mail-index-map-read.c	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-index-map-read.c	Fri Nov 11 17:00:39 2016 +0200
@@ -296,7 +296,8 @@
 
 /* returns -1 = error, 0 = index files are unusable,
    1 = index files are usable or at least repairable */
-static int mail_index_map_latest_file(struct mail_index *index)
+static int
+mail_index_map_latest_file(struct mail_index *index, const char **reason_r)
 {
 	struct mail_index_map *old_map, *new_map;
 	struct stat st;
@@ -305,7 +306,9 @@
 	const char *error;
 	int ret, try;
 
-	ret = mail_index_reopen_if_changed(index);
+	*reason_r = NULL;
+
+	ret = mail_index_reopen_if_changed(index, reason_r);
 	if (ret <= 0) {
 		if (ret < 0)
 			return -1;
@@ -361,6 +364,7 @@
 		} T_END;
 		if (ret != 0 || try == 2) {
 			if (ret < 0) {
+				*reason_r = "Corrupted index file";
 				unusable = TRUE;
 				ret = 0;
 			}
@@ -391,12 +395,14 @@
 
 	mail_index_unmap(&index->map);
 	index->map = new_map;
+	*reason_r = "Index mapped";
 	return 1;
 }
 
 int mail_index_map(struct mail_index *index,
 		   enum mail_index_sync_handler_type type)
 {
+	const char *reason;
 	int ret;
 
 	i_assert(!index->mapping);
@@ -410,7 +416,7 @@
 	if (index->initial_mapped) {
 		/* we're not creating/opening the index.
 		   sync this as a view from transaction log. */
-		ret = mail_index_sync_map(&index->map, type, FALSE);
+		ret = mail_index_sync_map(&index->map, type, FALSE, "initial mapping");
 	} else {
 		ret = 0;
 	}
@@ -421,7 +427,7 @@
 		   logs (which we'll also do even if the reopening succeeds).
 		   if index files are unusable (e.g. major version change)
 		   don't even try to use the transaction log. */
-		ret = mail_index_map_latest_file(index);
+		ret = mail_index_map_latest_file(index, &reason);
 		if (ret > 0) {
 			/* if we're creating the index file, we don't have any
 			   logs yet */
@@ -429,7 +435,7 @@
 				/* and update the map with the latest changes
 				   from transaction log */
 				ret = mail_index_sync_map(&index->map, type,
-							  TRUE);
+							  TRUE, reason);
 			}
 		} else if (ret == 0 && !index->readonly) {
 			/* make sure we don't try to open the file again */
--- a/src/lib-index/mail-index-private.h	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-index-private.h	Fri Nov 11 17:00:39 2016 +0200
@@ -257,7 +257,8 @@
 
 int mail_index_try_open_only(struct mail_index *index);
 void mail_index_close_file(struct mail_index *index);
-int mail_index_reopen_if_changed(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);
 
--- a/src/lib-index/mail-index-sync-private.h	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-index-sync-private.h	Fri Nov 11 17:00:39 2016 +0200
@@ -53,7 +53,8 @@
 			      enum mail_index_sync_handler_type type);
 void mail_index_sync_map_deinit(struct mail_index_sync_map_ctx *sync_map_ctx);
 int mail_index_sync_map(struct mail_index_map **map,
-			enum mail_index_sync_handler_type type, bool force);
+			enum mail_index_sync_handler_type type, bool force,
+			const char *sync_reason);
 
 int mail_index_sync_record(struct mail_index_sync_map_ctx *ctx,
 			   const struct mail_transaction_header *hdr,
--- a/src/lib-index/mail-index-sync-update.c	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-index-sync-update.c	Fri Nov 11 17:00:39 2016 +0200
@@ -899,7 +899,8 @@
 #endif
 
 int mail_index_sync_map(struct mail_index_map **_map,
-			enum mail_index_sync_handler_type type, bool force)
+			enum mail_index_sync_handler_type type, bool force,
+			const char *sync_reason)
 {
 	struct mail_index_map *map = *_map;
 	struct mail_index *index = map->index;
@@ -963,8 +964,10 @@
 		if (force && ret == 0) {
 			/* the seq/offset is probably broken */
 			mail_index_set_error(index, "Index %s: Lost log for "
-				"seq=%u offset=%"PRIuUOFF_T": %s", index->filepath,
-				map->hdr.log_file_seq, start_offset, reason);
+				"seq=%u offset=%"PRIuUOFF_T": %s "
+				"(initial_mapped=%d, reason=%s)", index->filepath,
+				map->hdr.log_file_seq, start_offset, reason,
+				index->initial_mapped, sync_reason);
 			(void)mail_index_fsck(index);
 		}
 		/* can't use it. sync by re-reading index. */
--- a/src/lib-index/mail-index.c	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-index.c	Fri Nov 11 17:00:39 2016 +0200
@@ -689,21 +689,27 @@
 	}
 }
 
-int mail_index_reopen_if_changed(struct mail_index *index)
+int mail_index_reopen_if_changed(struct mail_index *index,
+				 const char **reason_r)
 {
 	struct stat st1, st2;
+	int ret;
 
-	if (MAIL_INDEX_IS_IN_MEMORY(index))
+	if (MAIL_INDEX_IS_IN_MEMORY(index)) {
+		*reason_r = "in-memory index";
 		return 0;
+	}
 
 	if (index->fd == -1)
-		return mail_index_try_open_only(index);
+		goto final;
 
 	if ((index->flags & MAIL_INDEX_OPEN_FLAG_NFS_FLUSH) != 0)
 		nfs_flush_file_handle_cache(index->filepath);
 	if (nfs_safe_stat(index->filepath, &st2) < 0) {
-		if (errno == ENOENT)
+		if (errno == ENOENT) {
+			*reason_r = "index not found via stat()";
 			return 0;
+		}
 		mail_index_set_syscall_error(index, "stat()");
 		return -1;
 	}
@@ -714,17 +720,26 @@
 			return -1;
 		}
 		/* deleted/recreated, reopen */
+		*reason_r = "index is stale";
 	} else if (st1.st_ino == st2.st_ino &&
 		   CMP_DEV_T(st1.st_dev, st2.st_dev)) {
 		/* the same file */
+		*reason_r = "index unchanged";
 		return 1;
+	} else {
+		*reason_r = "index inode changed";
 	}
 
 	/* new file, new locks. the old fd can keep its locks, they don't
 	   matter anymore as no-one's going to modify the file. */
 	mail_index_close_file(index);
 
-	return mail_index_try_open_only(index);
+final:
+	if ((ret = mail_index_try_open_only(index)) == 0)
+		*reason_r = "index not found via open()";
+	else if (ret > 0)
+		*reason_r = "index opened";
+	return ret;
 }
 
 int mail_index_refresh(struct mail_index *index)
--- a/src/lib-index/mail-transaction-log-view.c	Thu Nov 10 23:00:59 2016 +0200
+++ b/src/lib-index/mail-transaction-log-view.c	Fri Nov 11 17:00:39 2016 +0200
@@ -2,6 +2,7 @@
 
 #include "lib.h"
 #include "array.h"
+#include "str.h"
 #include "mail-index-private.h"
 #include "mail-transaction-log-view-private.h"
 
@@ -58,6 +59,20 @@
 	i_free(view);
 }
 
+static const char *
+mail_transaction_log_get_file_seqs(struct mail_transaction_log *log)
+{
+	struct mail_transaction_log_file *file;
+	string_t *str = t_str_new(32);
+
+	if (log->files == NULL)
+		return "";
+
+	for (file = log->files; file != NULL; file = file->next)
+		str_printfa(str, ",%u", file->hdr.file_seq);
+	return str_c(str) + 1;
+}
+
 int mail_transaction_log_view_set(struct mail_transaction_log_view *view,
 				  uint32_t min_file_seq, uoff_t min_file_offset,
 				  uint32_t max_file_seq, uoff_t max_file_offset,
@@ -176,8 +191,9 @@
 				    file->hdr.file_seq > max_file_seq) {
 					/* missing files in the middle */
 					*reason_r = t_strdup_printf(
-						"Missing middle file seq=%u (between %u..%u)",
-						seq, min_file_seq, max_file_seq);
+						"Missing middle file seq=%u (between %u..%u, we have seqs %s)",
+						seq, min_file_seq, max_file_seq,
+						mail_transaction_log_get_file_seqs(view->log));
 					return 0;
 				}