dsync: When logging "Mailbox changed caused a desync", log also the r…

…eason.

The reason is usually somewhere in the debug logs, but it's difficult to
find from there.

src/doveadm/doveadm-dsync.c

@@ -333,13 +333,15 @@ static bool paths_are_equal(struct mail_user *user1, struct mail_user *user2,
 static int
 cmd_dsync_run_local(struct dsync_cmd_context *ctx, struct mail_user *user,
 		    struct dsync_brain *brain, struct dsync_ibc *ibc2,
-		    bool *changes_during_sync_r, enum mail_error *mail_error_r)
+		    const char **changes_during_sync_r,
+		    enum mail_error *mail_error_r)
 {
 	struct dsync_brain *brain2;
 	struct mail_user *user2;
 	struct setting_parser_context *set_parser;
 	const char *location;
 	bool brain1_running, brain2_running, changed1, changed2;
+	bool remote_only_changes;
 	int ret;
 
 	*mail_error_r = 0;
@@ -404,7 +406,7 @@ cmd_dsync_run_local(struct dsync_cmd_context *ctx, struct mail_user *user,
 		brain1_running = dsync_brain_run(brain, &changed1);
 		brain2_running = dsync_brain_run(brain2, &changed2);
 	}
-	*changes_during_sync_r = dsync_brain_has_unexpected_changes(brain2);
+	*changes_during_sync_r = t_strdup(dsync_brain_get_unexpected_changes_reason(brain2, &remote_only_changes));
 	if (dsync_brain_deinit(&brain2, mail_error_r) < 0)
 		return -1;
 	return doveadm_is_killed() ? -1 : 0;
@@ -557,7 +559,8 @@ cmd_dsync_run(struct doveadm_mail_cmd_context *_ctx, struct mail_user *user)
 	enum dsync_brain_flags brain_flags;
 	enum mail_error mail_error = 0, mail_error2;
 	bool remote_errors_logged = FALSE;
-	bool changes_during_sync = FALSE;
+	const char *changes_during_sync, *changes_during_sync2 = NULL;
+	bool remote_only_changes;
 	int ret = 0;
 
 	memset(&set, 0, sizeof(set));
@@ -644,7 +647,7 @@ cmd_dsync_run(struct doveadm_mail_cmd_context *_ctx, struct mail_user *user)
 	switch (ctx->run_type) {
 	case DSYNC_RUN_TYPE_LOCAL:
 		if (cmd_dsync_run_local(ctx, user, brain, ibc2,
-					&changes_during_sync, &mail_error) < 0)
+					&changes_during_sync2, &mail_error) < 0)
 			ret = -1;
 		break;
 	case DSYNC_RUN_TYPE_CMD:
@@ -662,12 +665,16 @@ cmd_dsync_run(struct doveadm_mail_cmd_context *_ctx, struct mail_user *user)
 		doveadm_print(str_c(state_str));
 	}
 
-	if (dsync_brain_has_unexpected_changes(brain) || changes_during_sync) {
+	changes_during_sync = dsync_brain_get_unexpected_changes_reason(brain, &remote_only_changes);
+	if (changes_during_sync != NULL || changes_during_sync2 != NULL) {
 		/* don't log a warning when running via doveadm server
 		   (e.g. called by replicator) */
 		if (ctx->ctx.conn == NULL) {
 			i_warning("Mailbox changes caused a desync. "
-				  "You may want to run dsync again.");
+				  "You may want to run dsync again: %s",
+				  changes_during_sync == NULL ||
+				  (remote_only_changes && changes_during_sync2 != NULL) ?
+				  changes_during_sync2 : changes_during_sync);
 		}
 		ctx->ctx.exit_code = 2;
 	}

src/doveadm/dsync/dsync-brain-mailbox-tree-sync.c

@@ -134,13 +134,9 @@ int dsync_brain_mailbox_tree_sync_change(struct dsync_brain *brain,
 			return -1;
 		}
 		if (ret == 0) {
-			if (brain->debug) {
-				i_debug("brain %c: Change during sync: "
-					"Mailbox GUID %s deletion conflict: %s",
-					brain->master_brain ? 'M' : 'S',
-					guid_128_to_string(change->mailbox_guid), errstr);
-			}
-			brain->changes_during_sync = TRUE;
+			dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+				"Mailbox GUID %s deletion conflict: %s",
+				guid_128_to_string(change->mailbox_guid), errstr));
 			return 0;
 		}
 		break;
@@ -153,13 +149,9 @@ int dsync_brain_mailbox_tree_sync_change(struct dsync_brain *brain,
 		errstr = mailbox_list_get_last_error(change->ns->list, &error);
 		if (error == MAIL_ERROR_NOTFOUND ||
 		    error == MAIL_ERROR_EXISTS) {
-			if (brain->debug) {
-				i_debug("brain %c: Change during sync: "
-					"Mailbox %s mailbox_list_delete_dir conflict: %s",
-					brain->master_brain ? 'M' : 'S',
-					change->full_name, errstr);
-			}
-			brain->changes_during_sync = TRUE;
+			dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+				"Mailbox %s mailbox_list_delete_dir conflict: %s",
+				change->full_name, errstr));
 			return 0;
 		} else {
 			i_error("Mailbox sync: mailbox_list_delete_dir failed: %s",
@@ -220,14 +212,9 @@ int dsync_brain_mailbox_tree_sync_change(struct dsync_brain *brain,
 		    error == MAIL_ERROR_NOTFOUND) {
 			/* mailbox was already created or was already deleted.
 			   let the next sync figure out what to do */
-			if (brain->debug) {
-				i_debug("brain %c: Change during sync: "
-					"Mailbox %s %s conflict: %s",
-					brain->master_brain ? 'M' : 'S',
-					mailbox_get_vname(box),
-					func_name, errstr);
-			}
-			brain->changes_during_sync = TRUE;
+			dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+				"Mailbox %s %s conflict: %s",
+				mailbox_get_vname(box), func_name, errstr));
 			ret = 0;
 		} else {
 			i_error("Mailbox %s sync: %s failed: %s",

src/doveadm/dsync/dsync-brain-mailbox.c

@@ -309,7 +309,8 @@ int dsync_brain_sync_mailbox_open(struct dsync_brain *brain,
 		i_warning("Failed to do incremental sync for mailbox %s, "
 			  "retry with a full sync (%s)",
 			  mailbox_get_vname(brain->box), desync_reason);
-		brain->changes_during_sync = TRUE;
+		dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+			"Incremental sync failed: %s", desync_reason));
 		brain->require_full_resync = TRUE;
 		return 0;
 	}
@@ -363,7 +364,8 @@ void dsync_brain_sync_mailbox_deinit(struct dsync_brain *brain)
 	if (brain->box_importer != NULL) {
 		uint32_t last_common_uid, last_messages_count;
 		uint64_t last_common_modseq, last_common_pvt_modseq;
-		bool changes_during_sync, require_full_resync;
+		const char *changes_during_sync;
+		bool require_full_resync;
 
 		i_assert(brain->failed);
 		(void)dsync_mailbox_import_deinit(&brain->box_importer,
@@ -671,12 +673,14 @@ dsync_cache_fields_update(const struct dsync_mailbox *local_box,
 bool dsync_brain_mailbox_update_pre(struct dsync_brain *brain,
 				    struct mailbox *box,
 				    const struct dsync_mailbox *local_box,
-				    const struct dsync_mailbox *remote_box)
+				    const struct dsync_mailbox *remote_box,
+				    const char **reason_r)
 {
 	struct mailbox_update update;
 	const struct dsync_mailbox_state *state;
 	bool ret = TRUE;
 
+	*reason_r = NULL;
 	memset(&update, 0, sizeof(update));
 
 	if (local_box->uid_validity != remote_box->uid_validity) {
@@ -693,6 +697,7 @@ bool dsync_brain_mailbox_update_pre(struct dsync_brain *brain,
 			   session, because the other side already started
 			   sending mailbox changes, but not for all mails. */
 			dsync_mailbox_state_remove(brain, local_box->mailbox_guid);
+			*reason_r = "UIDVALIDITY changed during a stateful sync, need to restart";
 			ret = FALSE;
 		}
 	}
@@ -738,7 +743,7 @@ bool dsync_brain_slave_recv_mailbox(struct dsync_brain *brain)
 	const struct dsync_mailbox *dsync_box;
 	struct dsync_mailbox local_dsync_box;
 	struct mailbox *box;
-	const char *errstr;
+	const char *errstr, *resync_reason;
 	enum mail_error error;
 	int ret;
 	bool resync;
@@ -774,13 +779,9 @@ bool dsync_brain_slave_recv_mailbox(struct dsync_brain *brain)
 			return TRUE;
 		}
 		//FIXME: verify this from log, and if not log an error.
-		if (brain->debug) {
-			i_debug("brain %c: Change during sync: "
-				"Mailbox GUID %s was lost",
-				brain->master_brain ? 'M' : 'S',
-				guid_128_to_string(dsync_box->mailbox_guid));
-		}
-		brain->changes_during_sync = TRUE;
+		dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+			"Mailbox GUID %s was lost",
+			guid_128_to_string(dsync_box->mailbox_guid)));
 		dsync_brain_slave_send_mailbox_lost(brain, dsync_box);
 		return TRUE;
 	}
@@ -814,7 +815,7 @@ bool dsync_brain_slave_recv_mailbox(struct dsync_brain *brain)
 			sizeof(dsync_box->mailbox_guid)) == 0);
 
 	resync = !dsync_brain_mailbox_update_pre(brain, box, &local_dsync_box,
-						 dsync_box);
+						 dsync_box, &resync_reason);
 
 	if (!dsync_boxes_need_sync(brain, &local_dsync_box, dsync_box)) {
 		/* no fields appear to have changed, skip this mailbox */
@@ -832,8 +833,9 @@ bool dsync_brain_slave_recv_mailbox(struct dsync_brain *brain)
 	dsync_brain_sync_mailbox_init(brain, box, &local_dsync_box, FALSE);
 	if ((ret = dsync_brain_sync_mailbox_open(brain, dsync_box)) < 0)
 		return TRUE;
+	if (resync)
+		dsync_brain_set_changes_during_sync(brain, resync_reason);
 	if (ret == 0 || resync) {
-		brain->changes_during_sync = TRUE;
 		brain->require_full_resync = TRUE;
 		dsync_brain_sync_mailbox_deinit(brain);
 		dsync_brain_slave_send_mailbox_lost(brain, dsync_box);

src/doveadm/dsync/dsync-brain-mails.c

@@ -21,6 +21,7 @@ const char *dsync_box_state_names[DSYNC_BOX_STATE_DONE+1] = {
 static bool dsync_brain_master_sync_recv_mailbox(struct dsync_brain *brain)
 {
 	const struct dsync_mailbox *dsync_box;
+	const char *resync_reason;
 	enum dsync_ibc_recv_ret ret;
 	bool resync;
 
@@ -43,14 +44,16 @@ static bool dsync_brain_master_sync_recv_mailbox(struct dsync_brain *brain)
 	if (dsync_box->mailbox_lost) {
 		/* remote lost the mailbox. it's probably already deleted, but
 		   verify it on next sync just to be sure */
-		brain->changes_during_sync = TRUE;
+		dsync_brain_set_changes_during_sync(brain, t_strdup_printf(
+			"Remote lost mailbox GUID %s (maybe it was just deleted?)",
+			guid_128_to_string(dsync_box->mailbox_guid)));
 		brain->require_full_resync = TRUE;
 		dsync_brain_sync_mailbox_deinit(brain);
 		return TRUE;
 	}
 	resync = !dsync_brain_mailbox_update_pre(brain, brain->box,
 						 &brain->local_dsync_box,
-						 dsync_box);
+						 dsync_box, &resync_reason);
 
 	if (!dsync_boxes_need_sync(brain, &brain->local_dsync_box, dsync_box)) {
 		/* no fields appear to have changed, skip this mailbox */
@@ -59,8 +62,9 @@ static bool dsync_brain_master_sync_recv_mailbox(struct dsync_brain *brain)
 	}
 	if ((ret = dsync_brain_sync_mailbox_open(brain, dsync_box)) < 0)
 		return TRUE;
+	if (resync)
+		dsync_brain_set_changes_during_sync(brain, resync_reason);
 	if (ret == 0 || resync) {
-		brain->changes_during_sync = TRUE;
 		brain->require_full_resync = TRUE;
 		brain->failed = TRUE;
 		dsync_brain_sync_mailbox_deinit(brain);
@@ -219,6 +223,7 @@ static bool dsync_brain_send_mail_request(struct dsync_brain *brain)
 static void dsync_brain_sync_half_finished(struct dsync_brain *brain)
 {
 	struct dsync_mailbox_state state;
+	const char *changes_during_sync;
 	bool require_full_resync;
 
 	if (brain->box_recv_state < DSYNC_BOX_STATE_RECV_LAST_COMMON ||
@@ -246,7 +251,7 @@ static void dsync_brain_sync_half_finished(struct dsync_brain *brain)
 						&state.last_common_modseq,
 						&state.last_common_pvt_modseq,
 						&state.last_messages_count,
-						&state.changes_during_sync,
+						&changes_during_sync,
 						&require_full_resync,
 						&brain->mail_error) < 0) {
 			if (require_full_resync) {
@@ -259,8 +264,10 @@ static void dsync_brain_sync_half_finished(struct dsync_brain *brain)
 				brain->failed = TRUE;
 			}
 		}
-		if (state.changes_during_sync)
-			brain->changes_during_sync = TRUE;
+		if (changes_during_sync != NULL) {
+			state.changes_during_sync = TRUE;
+			dsync_brain_set_changes_during_sync(brain, changes_during_sync);
+		}
 	}
 	if (brain->require_full_resync) {
 		state.last_uidvalidity = 0;
@@ -352,7 +359,7 @@ static bool dsync_brain_recv_last_common(struct dsync_brain *brain)
 	if (brain->mailbox_state.last_common_pvt_modseq > state.last_common_pvt_modseq)
 		brain->mailbox_state.last_common_pvt_modseq = state.last_common_pvt_modseq;
 	if (state.changes_during_sync)
-		brain->changes_during_sync = TRUE;
+		brain->changes_during_remote_sync = TRUE;
 
 	dsync_brain_sync_mailbox_deinit(brain);
 	return TRUE;

src/doveadm/dsync/dsync-brain-private.h

@@ -97,6 +97,7 @@ struct dsync_brain {
 	/* new states for synced mailboxes */
 	ARRAY_TYPE(dsync_mailbox_state) remote_mailbox_states;
 
+	const char *changes_during_sync;
 	enum mail_error mail_error;
 
 	unsigned int master_brain:1;
@@ -110,7 +111,7 @@ struct dsync_brain {
 	unsigned int no_backup_overwrite:1;
 	unsigned int no_mail_prefetch:1;
 	unsigned int no_mailbox_renames:1;
-	unsigned int changes_during_sync:1;
+	unsigned int changes_during_remote_sync:1;
 	unsigned int require_full_resync:1;
 	unsigned int verbose_proctitle:1;
 	unsigned int no_notify:1;
@@ -137,11 +138,14 @@ int dsync_brain_mailbox_alloc(struct dsync_brain *brain, const guid_128_t guid,
 bool dsync_brain_mailbox_update_pre(struct dsync_brain *brain,
 				    struct mailbox *box,
 				    const struct dsync_mailbox *local_box,
-				    const struct dsync_mailbox *remote_box);
+				    const struct dsync_mailbox *remote_box,
+				    const char **reason_r);
 bool dsync_boxes_need_sync(struct dsync_brain *brain,
 			   const struct dsync_mailbox *box1,
 			   const struct dsync_mailbox *box2);
 void dsync_brain_sync_init_box_states(struct dsync_brain *brain);
+void dsync_brain_set_changes_during_sync(struct dsync_brain *brain,
+					 const char *reason);
 
 void dsync_brain_master_send_mailbox(struct dsync_brain *brain);
 bool dsync_brain_slave_recv_mailbox(struct dsync_brain *brain);

src/doveadm/dsync/dsync-brain.c

@@ -765,8 +765,15 @@ bool dsync_brain_has_failed(struct dsync_brain *brain)
 	return brain->failed;
 }
 
-bool dsync_brain_has_unexpected_changes(struct dsync_brain *brain)
+const char *dsync_brain_get_unexpected_changes_reason(struct dsync_brain *brain,
+						      bool *remote_only_r)
 {
+	if (brain->changes_during_sync == NULL &&
+	    brain->changes_during_remote_sync) {
+		*remote_only_r = TRUE;
+		return "Remote notified that changes happened during sync";
+	}
+	*remote_only_r = FALSE;
 	return brain->changes_during_sync;
 }
 
@@ -798,3 +805,14 @@ bool dsync_brain_want_namespace(struct dsync_brain *brain,
 			      SETTING_STRVAR_UNEXPANDED) == 0;
 	}
 }
+
+void dsync_brain_set_changes_during_sync(struct dsync_brain *brain,
+					 const char *reason)
+{
+	if (brain->debug) {
+		i_debug("brain %c: Change during sync: %s",
+			brain->master_brain ? 'M' : 'S', reason);
+	}
+	if (brain->changes_during_sync == NULL)
+		brain->changes_during_sync = p_strdup(brain->pool, reason);
+}

src/doveadm/dsync/dsync-brain.h

@@ -104,8 +104,11 @@ bool dsync_brain_has_failed(struct dsync_brain *brain);
 void dsync_brain_get_state(struct dsync_brain *brain, string_t *output);
 /* Returns the sync type that was used. Mainly useful with slave brain. */
 enum dsync_brain_sync_type dsync_brain_get_sync_type(struct dsync_brain *brain);
-/* Returns TRUE if there were any unexpected changes during the sync. */
-bool dsync_brain_has_unexpected_changes(struct dsync_brain *brain);
+/* If there were any unexpected changes during the sync, return the reason
+   for them. Otherwise return NULL. If remote_only_r=TRUE, this brain itself
+   didn't see any changes, but the remote brain did. */
+const char *dsync_brain_get_unexpected_changes_reason(struct dsync_brain *brain,
+						      bool *remote_only_r);
 /* Returns TRUE if we want to sync this namespace. */
 bool dsync_brain_want_namespace(struct dsync_brain *brain,
 				struct mail_namespace *ns);