dsync: When logging "Mailbox changed caused a desync", log also the reason.

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

diff --git a/src/doveadm/doveadm-dsync.c b/src/doveadm/doveadm-dsync.c
index a19596b4005f71488c109c43937b72b97db0aaf6..8288637b7d10db0c23d10856b153549851a5e5d3 100644 (file)
--- a/src/doveadm/doveadm-dsync.c
+++ b/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;
        }

diff --git a/src/doveadm/dsync/dsync-brain-mailbox-tree-sync.c b/src/doveadm/dsync/dsync-brain-mailbox-tree-sync.c
index 5d67c694703fcf3b989325b13f9b90e3e36d5500..618154ff1401d1687e94eaf373d1ea86cde32c95 100644 (file)
--- a/src/doveadm/dsync/dsync-brain-mailbox-tree-sync.c
+++ b/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",

diff --git a/src/doveadm/dsync/dsync-brain-mailbox.c b/src/doveadm/dsync/dsync-brain-mailbox.c
index 502a2489133999c9d716e8a9ea0bc283fed40556..e62a658e387922e4a9648aad9f89ef86973e9ba0 100644 (file)
--- a/src/doveadm/dsync/dsync-brain-mailbox.c
+++ b/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);

diff --git a/src/doveadm/dsync/dsync-brain-mails.c b/src/doveadm/dsync/dsync-brain-mails.c
index 5a934e4f662927393f1b9d2604d4024e19ab0543..6db6c26725ed9cb9ab762e73bdbadfe5a490882d 100644 (file)
--- a/src/doveadm/dsync/dsync-brain-mails.c
+++ b/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;

diff --git a/src/doveadm/dsync/dsync-brain-private.h b/src/doveadm/dsync/dsync-brain-private.h
index 69fda3eb77043015b66e81685768364dec13f147..f944d891695fe12233cf260e73e355e4e20ad470 100644 (file)
--- a/src/doveadm/dsync/dsync-brain-private.h
+++ b/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);

diff --git a/src/doveadm/dsync/dsync-brain.c b/src/doveadm/dsync/dsync-brain.c
index 3935b5f88c2d7b9848d447daccd44bf53df8e99a..643e790ae7a02357eb6c1675c646d55f4bc8f291 100644 (file)
--- a/src/doveadm/dsync/dsync-brain.c
+++ b/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);
+}

diff --git a/src/doveadm/dsync/dsync-brain.h b/src/doveadm/dsync/dsync-brain.h
index 259ade1c4f09c1cb7a002a534bfb09ba39662b7d..5027378a11e8771147a4b0738dfc7ca720c0a44f 100644 (file)
--- a/src/doveadm/dsync/dsync-brain.h
+++ b/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);

diff --git a/src/doveadm/dsync/dsync-mailbox-import.c b/src/doveadm/dsync/dsync-mailbox-import.c
index c7e853f147f246407ba461250ec65e731cd9461e..9d71297dbcf82ad4ac2be6b0d7f00558ef7630a5 100644 (file)
--- a/src/doveadm/dsync/dsync-mailbox-import.c
+++ b/src/doveadm/dsync/dsync-mailbox-import.c
@@ -2595,7 +2595,7 @@ reassign_uids_in_seq_range(struct dsync_mailbox_importer *importer,
 
 static int
 reassign_unwanted_uids(struct dsync_mailbox_importer *importer,
-                      bool *changes_during_sync_r)
+                      const char **changes_during_sync_r)
 {
        ARRAY_TYPE(seq_range) unwanted_uids;
        const uint32_t *wanted_uids, *saved_uids;
@@ -2639,7 +2639,9 @@ reassign_unwanted_uids(struct dsync_mailbox_importer *importer,
 
        ret = reassign_uids_in_seq_range(importer, &unwanted_uids);
        if (ret == 0) {
-               *changes_during_sync_r = TRUE;
+               *changes_during_sync_r = t_strdup_printf(
+                       "%u UIDs changed due to UID conflicts",
+                       seq_range_count(&unwanted_uids));
                /* conflicting changes during sync, revert our last-common-uid
                   back to a safe value. */
                importer->last_common_uid = importer->local_uid_next - 1;
@@ -2700,7 +2702,7 @@ dsync_mailbox_import_commit(struct dsync_mailbox_importer *importer, bool final)
 }
 
 static int dsync_mailbox_import_finish(struct dsync_mailbox_importer *importer,
-                                      bool *changes_during_sync_r)
+                                      const char **changes_during_sync_r)
 {
        struct mailbox_update update;
        int ret;
@@ -2803,7 +2805,7 @@ int dsync_mailbox_import_deinit(struct dsync_mailbox_importer **_importer,
                                uint64_t *last_common_modseq_r,
                                uint64_t *last_common_pvt_modseq_r,
                                uint32_t *last_messages_count_r,
-                               bool *changes_during_sync_r,
+                               const char **changes_during_sync_r,
                                bool *require_full_resync_r,
                                enum mail_error *error_r)
 {
@@ -2812,7 +2814,7 @@ int dsync_mailbox_import_deinit(struct dsync_mailbox_importer **_importer,
        int ret;
 
        *_importer = NULL;
-       *changes_during_sync_r = FALSE;
+       *changes_during_sync_r = NULL;
        *require_full_resync_r = importer->require_full_resync;
 
        if ((!success || importer->require_full_resync) && !importer->failed) {

diff --git a/src/doveadm/dsync/dsync-mailbox-import.h b/src/doveadm/dsync/dsync-mailbox-import.h
index 28f388b11a534c51962be4abe3a0e806f03cd28b..50d74abf6c3d4a8a9e44b14455e36703c07d7c00 100644 (file)
--- a/src/doveadm/dsync/dsync-mailbox-import.h
+++ b/src/doveadm/dsync/dsync-mailbox-import.h
@@ -52,7 +52,7 @@ int dsync_mailbox_import_deinit(struct dsync_mailbox_importer **importer,
                                uint64_t *last_common_modseq_r,
                                uint64_t *last_common_pvt_modseq_r,
                                uint32_t *last_messages_count_r,
-                               bool *changes_during_sync_r,
+                               const char **changes_during_sync_r,
                                bool *require_full_resync_r,
                                enum mail_error *error_r);