drbd: log UUIDs whenever they change

All decisions about sync, sync direction, and wether or not to
allow a connect or attach are based on our set of UUIDs to tag a
data generation.

Log changes to the UUIDs whenever they occur,
logging "new current UUID P:Q:R:S" is more useful
than "Creating new current UUID".

Signed-off-by: Philipp Reisner <philipp.reisner@linbit.com>
Signed-off-by: Lars Ellenberg <lars.ellenberg@linbit.com>

5 files changed, 58 insertions, 51 deletions

diff --git a/drivers/block/drbd/drbd_int.h b/drivers/block/drbd/drbd_int.h
index cfe7fff459e3..0a9059eb94db 100644
--- a/drivers/block/drbd/drbd_int.h
+++ b/drivers/block/drbd/drbd_int.h
@@ -1240,11 +1240,11 @@ extern int _drbd_send_bitmap(struct drbd_conf *mdev);
 extern int drbd_send_sr_reply(struct drbd_conf *mdev, enum drbd_state_rv retcode);
 extern void drbd_free_bc(struct drbd_backing_dev *ldev);
 extern void drbd_mdev_cleanup(struct drbd_conf *mdev);
+void drbd_print_uuids(struct drbd_conf *mdev, const char *text);
 
 /* drbd_meta-data.c (still in drbd_main.c) */
 extern void drbd_md_sync(struct drbd_conf *mdev);
 extern int  drbd_md_read(struct drbd_conf *mdev, struct drbd_backing_dev *bdev);
-/* maybe define them below as inline? */
 extern void drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local);
 extern void _drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local);
 extern void drbd_uuid_new_current(struct drbd_conf *mdev) __must_hold(local);
@@ -2360,9 +2360,11 @@ static inline void dec_ap_bio(struct drbd_conf *mdev)
         }
 }
 
-static inline void drbd_set_ed_uuid(struct drbd_conf *mdev, u64 val)
+static inline int drbd_set_ed_uuid(struct drbd_conf *mdev, u64 val)
 {
+        int changed = mdev->ed_uuid != val;
         mdev->ed_uuid = val;
+        return changed;
 }
 
 static inline int seq_cmp(u32 a, u32 b)
diff --git a/drivers/block/drbd/drbd_main.c b/drivers/block/drbd/drbd_main.c
index e0be4077d564..b68332a0e73e 100644
--- a/drivers/block/drbd/drbd_main.c
+++ b/drivers/block/drbd/drbd_main.c
@@ -1159,6 +1159,10 @@ __drbd_set_state(struct drbd_conf *mdev, union drbd_state ns,
                 atomic_inc(&mdev->local_cnt);
 
         mdev->state = ns;
+
+        if (os.disk == D_ATTACHING && ns.disk >= D_NEGOTIATING)
+                drbd_print_uuids(mdev, "attached to UUIDs");
+
         wake_up(&mdev->misc_wait);
         wake_up(&mdev->state_wait);
 
@@ -2035,6 +2039,24 @@ int drbd_send_uuids_skip_initial_sync(struct drbd_conf *mdev)
         return _drbd_send_uuids(mdev, 8);
 }
 
+void drbd_print_uuids(struct drbd_conf *mdev, const char *text)
+{
+        if (get_ldev_if_state(mdev, D_NEGOTIATING)) {
+                u64 *uuid = mdev->ldev->md.uuid;
+                dev_info(DEV, "%s %016llX:%016llX:%016llX:%016llX\n",
+                     text,
+                     (unsigned long long)uuid[UI_CURRENT],
+                     (unsigned long long)uuid[UI_BITMAP],
+                     (unsigned long long)uuid[UI_HISTORY_START],
+                     (unsigned long long)uuid[UI_HISTORY_END]);
+                put_ldev(mdev);
+        } else {
+                dev_info(DEV, "%s effective data uuid: %016llX\n",
+                                text,
+                                (unsigned long long)mdev->ed_uuid);
+        }
+}
+
 int drbd_gen_and_send_sync_uuid(struct drbd_conf *mdev)
 {
         struct p_rs_uuid p;
@@ -2044,6 +2066,7 @@ int drbd_gen_and_send_sync_uuid(struct drbd_conf *mdev)
 
         uuid = mdev->ldev->md.uuid[UI_BITMAP] + UUID_NEW_BM_OFFSET;
         drbd_uuid_set(mdev, UI_BITMAP, uuid);
+        drbd_print_uuids(mdev, "updated sync UUID");
         drbd_md_sync(mdev);
         p.uuid = cpu_to_be64(uuid);
 
@@ -3749,28 +3772,6 @@ int drbd_md_read(struct drbd_conf *mdev, struct drbd_backing_dev *bdev)
         return rv;
 }
 
-static void debug_drbd_uuid(struct drbd_conf *mdev, enum drbd_uuid_index index)
-{
-        static char *uuid_str[UI_EXTENDED_SIZE] = {
-                [UI_CURRENT] = "CURRENT",
-                [UI_BITMAP] = "BITMAP",
-                [UI_HISTORY_START] = "HISTORY_START",
-                [UI_HISTORY_END] = "HISTORY_END",
-                [UI_SIZE] = "SIZE",
-                [UI_FLAGS] = "FLAGS",
-        };
-
-        if (index >= UI_EXTENDED_SIZE) {
-                dev_warn(DEV, " uuid_index >= EXTENDED_SIZE\n");
-                return;
-        }
-
-        dynamic_dev_dbg(DEV, " uuid[%s] now %016llX\n",
-                 uuid_str[index],
-                 (unsigned long long)mdev->ldev->md.uuid[index]);
-}
-
-
 /**
  * drbd_md_mark_dirty() - Mark meta data super block as dirty
  * @mdev:       DRBD device.
@@ -3800,10 +3801,8 @@ static void drbd_uuid_move_history(struct drbd_conf *mdev) __must_hold(local)
 {
         int i;
 
-        for (i = UI_HISTORY_START; i < UI_HISTORY_END; i++) {
+        for (i = UI_HISTORY_START; i < UI_HISTORY_END; i++)
                 mdev->ldev->md.uuid[i+1] = mdev->ldev->md.uuid[i];
-                debug_drbd_uuid(mdev, i+1);
-        }
 }
 
 void _drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local)
@@ -3818,7 +3817,6 @@ void _drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local)
         }
 
         mdev->ldev->md.uuid[idx] = val;
-        debug_drbd_uuid(mdev, idx);
         drbd_md_mark_dirty(mdev);
 }
 
@@ -3828,7 +3826,6 @@ void drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local)
         if (mdev->ldev->md.uuid[idx]) {
                 drbd_uuid_move_history(mdev);
                 mdev->ldev->md.uuid[UI_HISTORY_START] = mdev->ldev->md.uuid[idx];
-                debug_drbd_uuid(mdev, UI_HISTORY_START);
         }
         _drbd_uuid_set(mdev, idx, val);
 }
@@ -3843,14 +3840,16 @@ void drbd_uuid_set(struct drbd_conf *mdev, int idx, u64 val) __must_hold(local)
 void drbd_uuid_new_current(struct drbd_conf *mdev) __must_hold(local)
 {
         u64 val;
+        unsigned long long bm_uuid = mdev->ldev->md.uuid[UI_BITMAP];
+
+        if (bm_uuid)
+                dev_warn(DEV, "bm UUID was already set: %llX\n", bm_uuid);
 
-        dev_info(DEV, "Creating new current UUID\n");
-        D_ASSERT(mdev->ldev->md.uuid[UI_BITMAP] == 0);
         mdev->ldev->md.uuid[UI_BITMAP] = mdev->ldev->md.uuid[UI_CURRENT];
-        debug_drbd_uuid(mdev, UI_BITMAP);
 
         get_random_bytes(&val, sizeof(u64));
         _drbd_uuid_set(mdev, UI_CURRENT, val);
+        drbd_print_uuids(mdev, "new current UUID");
         /* get it to stable storage _now_ */
         drbd_md_sync(mdev);
 }
@@ -3864,16 +3863,12 @@ void drbd_uuid_set_bm(struct drbd_conf *mdev, u64 val) __must_hold(local)
                 drbd_uuid_move_history(mdev);
                 mdev->ldev->md.uuid[UI_HISTORY_START] = mdev->ldev->md.uuid[UI_BITMAP];
                 mdev->ldev->md.uuid[UI_BITMAP] = 0;
-                debug_drbd_uuid(mdev, UI_HISTORY_START);
-                debug_drbd_uuid(mdev, UI_BITMAP);
         } else {
-                if (mdev->ldev->md.uuid[UI_BITMAP])
-                        dev_warn(DEV, "bm UUID already set");
-
-                mdev->ldev->md.uuid[UI_BITMAP] = val;
-                mdev->ldev->md.uuid[UI_BITMAP] &= ~((u64)1);
+                unsigned long long bm_uuid = mdev->ldev->md.uuid[UI_BITMAP];
+                if (bm_uuid)
+                        dev_warn(DEV, "bm UUID was already set: %llX\n", bm_uuid);
 
-                debug_drbd_uuid(mdev, UI_BITMAP);
+                mdev->ldev->md.uuid[UI_BITMAP] = val & ~((u64)1);
         }
         drbd_md_mark_dirty(mdev);
 }
diff --git a/drivers/block/drbd/drbd_nl.c b/drivers/block/drbd/drbd_nl.c
index ffe3a97fef9b..ce6f2fe80852 100644
--- a/drivers/block/drbd/drbd_nl.c
+++ b/drivers/block/drbd/drbd_nl.c
@@ -2151,6 +2151,7 @@ static int drbd_nl_new_c_uuid(struct drbd_conf *mdev, struct drbd_nl_cfg_req *nl
                 if (skip_initial_sync) {
                         drbd_send_uuids_skip_initial_sync(mdev);
                         _drbd_uuid_set(mdev, UI_BITMAP, 0);
+                        drbd_print_uuids(mdev, "cleared bitmap UUID");
                         spin_lock_irq(&mdev->req_lock);
                         _drbd_set_state(_NS2(mdev, disk, D_UP_TO_DATE, pdsk, D_UP_TO_DATE),
                                         CS_VERBOSE, NULL);
diff --git a/drivers/block/drbd/drbd_receiver.c b/drivers/block/drbd/drbd_receiver.c
index e9354931eace..e5686a81f42c 100644
--- a/drivers/block/drbd/drbd_receiver.c
+++ b/drivers/block/drbd/drbd_receiver.c
@@ -3024,7 +3024,7 @@ static int receive_uuids(struct drbd_conf *mdev, enum drbd_packets cmd, unsigned
 {
         struct p_uuids *p = &mdev->data.rbuf.uuids;
         u64 *p_uuid;
-        int i;
+        int i, updated_uuids = 0;
 
         p_uuid = kmalloc(sizeof(u64)*UI_EXTENDED_SIZE, GFP_NOIO);
 
@@ -3059,13 +3059,14 @@ static int receive_uuids(struct drbd_conf *mdev, enum drbd_packets cmd, unsigned
                         _drbd_set_state(_NS2(mdev, disk, D_UP_TO_DATE, pdsk, D_UP_TO_DATE),
                                         CS_VERBOSE, NULL);
                         drbd_md_sync(mdev);
+                        updated_uuids = 1;
                 }
                 put_ldev(mdev);
         } else if (mdev->state.disk < D_INCONSISTENT &&
                    mdev->state.role == R_PRIMARY) {
                 /* I am a diskless primary, the peer just created a new current UUID
                    for me. */
-                drbd_set_ed_uuid(mdev, p_uuid[UI_CURRENT]);
+                updated_uuids = drbd_set_ed_uuid(mdev, p_uuid[UI_CURRENT]);
         }
 
         /* Before we test for the disk state, we should wait until an eventually
@@ -3074,7 +3075,10 @@ static int receive_uuids(struct drbd_conf *mdev, enum drbd_packets cmd, unsigned
            new disk state... */
         wait_event(mdev->misc_wait, !test_bit(CLUSTER_ST_CHANGE, &mdev->flags));
         if (mdev->state.conn >= C_CONNECTED && mdev->state.disk < D_INCONSISTENT)
-                drbd_set_ed_uuid(mdev, p_uuid[UI_CURRENT]);
+                updated_uuids |= drbd_set_ed_uuid(mdev, p_uuid[UI_CURRENT]);
+
+        if (updated_uuids)
+                drbd_print_uuids(mdev, "receiver updated UUIDs to");
 
         return true;
 }
@@ -3305,6 +3309,7 @@ static int receive_sync_uuid(struct drbd_conf *mdev, enum drbd_packets cmd, unsi
                 _drbd_uuid_set(mdev, UI_CURRENT, be64_to_cpu(p->uuid));
                 _drbd_uuid_set(mdev, UI_BITMAP, 0UL);
 
+                drbd_print_uuids(mdev, "updated sync uuid");
                 drbd_start_resync(mdev, C_SYNC_TARGET);
 
                 put_ldev(mdev);
diff --git a/drivers/block/drbd/drbd_worker.c b/drivers/block/drbd/drbd_worker.c
index ec42e04bb517..ff0eb308ee4a 100644
--- a/drivers/block/drbd/drbd_worker.c
+++ b/drivers/block/drbd/drbd_worker.c
@@ -871,14 +871,18 @@ int drbd_resync_finished(struct drbd_conf *mdev)
                         }
                 }
 
-                drbd_uuid_set_bm(mdev, 0UL);
-
-                if (mdev->p_uuid) {
-                        /* Now the two UUID sets are equal, update what we
-                         * know of the peer. */
-                        int i;
-                        for (i = UI_CURRENT ; i <= UI_HISTORY_END ; i++)
-                                mdev->p_uuid[i] = mdev->ldev->md.uuid[i];
+                if (!(os.conn == C_VERIFY_S || os.conn == C_VERIFY_T)) {
+                        /* for verify runs, we don't update uuids here,
+                         * so there would be nothing to report. */
+                        drbd_uuid_set_bm(mdev, 0UL);
+                        drbd_print_uuids(mdev, "updated UUIDs");
+                        if (mdev->p_uuid) {
+                                /* Now the two UUID sets are equal, update what we
+                                 * know of the peer. */
+                                int i;
+                                for (i = UI_CURRENT ; i <= UI_HISTORY_END ; i++)
+                                        mdev->p_uuid[i] = mdev->ldev->md.uuid[i];
+                        }
                 }
         }