rbd-mirror: permit better tracking between image replayer and bootstrap

Signed-off-by: Jason Dillaman <dillaman@redhat.com>

diff --git a/src/tools/rbd_mirror/image_replayer/BootstrapRequest.cc b/src/tools/rbd_mirror/image_replayer/BootstrapRequest.cc
index 26d4188c18bdec69b9310b656363d6511f4c810c..7ce21b4bfe0783215a073307df0af4603d3e3807 100644 (file)
--- a/src/tools/rbd_mirror/image_replayer/BootstrapRequest.cc
+++ b/src/tools/rbd_mirror/image_replayer/BootstrapRequest.cc
@@ -28,7 +28,7 @@
 #define dout_subsys ceph_subsys_rbd_mirror
 #undef dout_prefix
 #define dout_prefix *_dout << "rbd::mirror::image_replayer::BootstrapRequest: " \
-                           << this << " " << __func__
+                           << this << " " << __func__ << ": "
 
 namespace rbd {
 namespace mirror {
@@ -67,6 +67,7 @@ BootstrapRequest<I>::BootstrapRequest(
     m_client_state(client_state), m_client_meta(client_meta),
     m_progress_ctx(progress_ctx), m_do_resync(do_resync),
     m_lock(unique_lock_name("BootstrapRequest::m_lock", this)) {
+  dout(10) << dendl;
 }
 
 template <typename I>
@@ -89,7 +90,7 @@ void BootstrapRequest<I>::send() {
 
 template <typename I>
 void BootstrapRequest<I>::cancel() {
-  dout(20) << dendl;
+  dout(10) << dendl;
 
   Mutex::Locker locker(m_lock);
   m_canceled = true;
@@ -101,7 +102,7 @@ void BootstrapRequest<I>::cancel() {
 
 template <typename I>
 void BootstrapRequest<I>::get_remote_tag_class() {
-  dout(20) << dendl;
+  dout(15) << dendl;
 
   update_progress("GET_REMOTE_TAG_CLASS");
 
@@ -113,10 +114,10 @@ void BootstrapRequest<I>::get_remote_tag_class() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_get_remote_tag_class(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": failed to retrieve remote client: " << cpp_strerror(r) << dendl;
+    derr << "failed to retrieve remote client: " << cpp_strerror(r) << dendl;
     finish(r);
     return;
   }
@@ -126,7 +127,7 @@ void BootstrapRequest<I>::handle_get_remote_tag_class(int r) {
   try {
     decode(client_data, it);
   } catch (const buffer::error &err) {
-    derr << ": failed to decode remote client meta data: " << err.what()
+    derr << "failed to decode remote client meta data: " << err.what()
          << dendl;
     finish(-EBADMSG);
     return;
@@ -135,20 +136,20 @@ void BootstrapRequest<I>::handle_get_remote_tag_class(int r) {
   librbd::journal::ImageClientMeta *client_meta =
     boost::get<librbd::journal::ImageClientMeta>(&client_data.client_meta);
   if (client_meta == nullptr) {
-    derr << ": unknown remote client registration" << dendl;
+    derr << "unknown remote client registration" << dendl;
     finish(-EINVAL);
     return;
   }
 
   m_remote_tag_class = client_meta->tag_class;
-  dout(10) << ": remote tag class=" << m_remote_tag_class << dendl;
+  dout(10) << "remote tag class=" << m_remote_tag_class << dendl;
 
   open_remote_image();
 }
 
 template <typename I>
 void BootstrapRequest<I>::open_remote_image() {
-  dout(20) << dendl;
+  dout(15) << "remote_image_id=" << m_remote_image_id << dendl;
 
   update_progress("OPEN_REMOTE_IMAGE");
 
@@ -163,10 +164,10 @@ void BootstrapRequest<I>::open_remote_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_open_remote_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": failed to open remote image: " << cpp_strerror(r) << dendl;
+    derr << "failed to open remote image: " << cpp_strerror(r) << dendl;
     ceph_assert(m_remote_image_ctx == nullptr);
     finish(r);
     return;
@@ -177,7 +178,7 @@ void BootstrapRequest<I>::handle_open_remote_image(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::is_primary() {
-  dout(20) << dendl;
+  dout(15) << dendl;
 
   update_progress("OPEN_REMOTE_IMAGE");
 
@@ -191,15 +192,15 @@ void BootstrapRequest<I>::is_primary() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_is_primary(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r == -ENOENT) {
-    dout(5) << ": remote image is not mirrored" << dendl;
+    dout(5) << "remote image is not mirrored" << dendl;
     m_ret_val = -EREMOTEIO;
     close_remote_image();
     return;
   } else if (r < 0) {
-    derr << ": error querying remote image primary status: " << cpp_strerror(r)
+    derr << "error querying remote image primary status: " << cpp_strerror(r)
          << dendl;
     m_ret_val = r;
     close_remote_image();
@@ -209,7 +210,7 @@ void BootstrapRequest<I>::handle_is_primary(int r) {
   if (!m_primary) {
     if (m_local_image_id.empty()) {
       // no local image and remote isn't primary -- don't sync it
-      dout(5) << ": remote image is not primary -- not syncing"
+      dout(5) << "remote image is not primary -- not syncing"
               << dendl;
       m_ret_val = -EREMOTEIO;
       close_remote_image();
@@ -217,7 +218,7 @@ void BootstrapRequest<I>::handle_is_primary(int r) {
     } else if (m_client_meta->state !=
                  librbd::journal::MIRROR_PEER_STATE_REPLAYING) {
       // ensure we attempt to re-sync to remote if it's re-promoted
-      dout(5) << ": remote image is not primary -- sync interrupted"
+      dout(5) << "remote image is not primary -- sync interrupted"
               << dendl;
       m_ret_val = -EREMOTEIO;
       update_client_state();
@@ -242,7 +243,7 @@ void BootstrapRequest<I>::handle_is_primary(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::update_client_state() {
-  dout(20) << dendl;
+  dout(15) << dendl;
   update_progress("UPDATE_CLIENT_STATE");
 
   librbd::journal::MirrorPeerClientMeta client_meta(*m_client_meta);
@@ -260,9 +261,9 @@ void BootstrapRequest<I>::update_client_state() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_update_client_state(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
   if (r < 0) {
-    derr << ": failed to update client: " << cpp_strerror(r) << dendl;
+    derr << "failed to update client: " << cpp_strerror(r) << dendl;
   } else {
     m_client_meta->state = librbd::journal::MIRROR_PEER_STATE_REPLAYING;
   }
@@ -272,7 +273,7 @@ void BootstrapRequest<I>::handle_update_client_state(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::open_local_image() {
-  dout(20) << dendl;
+  dout(15) << "local_image_id=" << m_local_image_id << dendl;
 
   update_progress("OPEN_LOCAL_IMAGE");
 
@@ -287,11 +288,11 @@ void BootstrapRequest<I>::open_local_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_open_local_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r == -ENOENT) {
     ceph_assert(*m_local_image_ctx == nullptr);
-    dout(10) << ": local image missing" << dendl;
+    dout(10) << "local image missing" << dendl;
     unregister_client();
     return;
   } else if (r == -EREMOTEIO) {
@@ -302,7 +303,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
     return;
   } else if (r < 0) {
     ceph_assert(*m_local_image_ctx == nullptr);
-    derr << ": failed to open local image: " << cpp_strerror(r) << dendl;
+    derr << "failed to open local image: " << cpp_strerror(r) << dendl;
     m_ret_val = r;
     close_remote_image();
     return;
@@ -314,7 +315,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
     if (local_image_ctx->journal == nullptr) {
       local_image_ctx->snap_lock.put_read();
 
-      derr << ": local image does not support journaling" << dendl;
+      derr << "local image does not support journaling" << dendl;
       m_ret_val = -EINVAL;
       close_local_image();
       return;
@@ -324,7 +325,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
     if (r < 0) {
       local_image_ctx->snap_lock.put_read();
 
-      derr << ": failed to check if a resync was requested" << dendl;
+      derr << "failed to check if a resync was requested" << dendl;
       m_ret_val = r;
       close_local_image();
       return;
@@ -332,7 +333,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
 
     m_local_tag_tid = local_image_ctx->journal->get_tag_tid();
     m_local_tag_data = local_image_ctx->journal->get_tag_data();
-    dout(10) << ": local tag=" << m_local_tag_tid << ", "
+    dout(10) << "local tag=" << m_local_tag_tid << ", "
              << "local tag data=" << m_local_tag_data << dendl;
     local_image_ctx->snap_lock.put_read();
   }
@@ -341,7 +342,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
     // if the local mirror is not linked to the (now) non-primary image,
     // stop the replay. Otherwise, we ignore that the remote is non-primary
     // so that we can replay the demotion
-    dout(5) << ": remote image is not primary -- skipping image replay"
+    dout(5) << "remote image is not primary -- skipping image replay"
             << dendl;
     m_ret_val = -EREMOTEIO;
     close_local_image();
@@ -354,7 +355,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
   }
 
   if (*m_client_state == cls::journal::CLIENT_STATE_DISCONNECTED) {
-    dout(10) << ": client flagged disconnected -- skipping bootstrap" << dendl;
+    dout(10) << "client flagged disconnected -- skipping bootstrap" << dendl;
     // The caller is expected to detect disconnect initializing remote journal.
     m_ret_val = 0;
     close_remote_image();
@@ -366,7 +367,7 @@ void BootstrapRequest<I>::handle_open_local_image(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::unregister_client() {
-  dout(20) << dendl;
+  dout(15) << dendl;
   update_progress("UNREGISTER_CLIENT");
 
   m_local_image_id = "";
@@ -378,9 +379,9 @@ void BootstrapRequest<I>::unregister_client() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_unregister_client(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
   if (r < 0) {
-    derr << ": failed to unregister with remote journal: " << cpp_strerror(r)
+    derr << "failed to unregister with remote journal: " << cpp_strerror(r)
          << dendl;
     m_ret_val = r;
     close_remote_image();
@@ -393,7 +394,7 @@ void BootstrapRequest<I>::handle_unregister_client(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::register_client() {
-  dout(20) << dendl;
+  dout(15) << dendl;
 
   update_progress("REGISTER_CLIENT");
 
@@ -413,10 +414,10 @@ void BootstrapRequest<I>::register_client() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_register_client(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": failed to register with remote journal: " << cpp_strerror(r)
+    derr << "failed to register with remote journal: " << cpp_strerror(r)
          << dendl;
     m_ret_val = r;
     close_remote_image();
@@ -432,12 +433,13 @@ void BootstrapRequest<I>::handle_register_client(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::update_client_image() {
-  dout(20) << dendl;
-  update_progress("UPDATE_CLIENT_IMAGE");
-
   ceph_assert(m_local_image_id.empty());
+  assert(m_local_image_id.empty());
   m_local_image_id = librbd::util::generate_image_id<I>(m_local_io_ctx);
 
+  dout(15) << "local_image_id=" << m_local_image_id << dendl;
+  update_progress("UPDATE_CLIENT_IMAGE");
+
   librbd::journal::MirrorPeerClientMeta client_meta{m_local_image_id};
   client_meta.state = librbd::journal::MIRROR_PEER_STATE_SYNCING;
 
@@ -453,17 +455,17 @@ void BootstrapRequest<I>::update_client_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_update_client_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": failed to update client: " << cpp_strerror(r) << dendl;
+    derr << "failed to update client: " << cpp_strerror(r) << dendl;
     m_ret_val = r;
     close_remote_image();
     return;
   }
 
   if (m_canceled) {
-    dout(10) << ": request canceled" << dendl;
+    dout(10) << "request canceled" << dendl;
     m_ret_val = -ECANCELED;
     close_remote_image();
     return;
@@ -476,7 +478,7 @@ void BootstrapRequest<I>::handle_update_client_image(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::create_local_image() {
-  dout(20) << dendl;
+  dout(15) << "local_image_id=" << m_local_image_id << dendl;
   update_progress("CREATE_LOCAL_IMAGE");
 
   m_remote_image_ctx->snap_lock.get_read();
@@ -494,18 +496,18 @@ void BootstrapRequest<I>::create_local_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_create_local_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r == -EBADF) {
-    dout(5) << ": image id " << m_local_image_id << " already in-use" << dendl;
+    dout(5) << "image id " << m_local_image_id << " already in-use" << dendl;
     m_local_image_id = "";
     update_client_image();
     return;
   } else if (r < 0) {
     if (r == -ENOENT) {
-      dout(10) << ": parent image does not exist" << dendl;
+      dout(10) << "parent image does not exist" << dendl;
     } else {
-      derr << ": failed to create local image: " << cpp_strerror(r) << dendl;
+      derr << "failed to create local image: " << cpp_strerror(r) << dendl;
     }
     m_ret_val = r;
     close_remote_image();
@@ -524,7 +526,7 @@ void BootstrapRequest<I>::get_remote_tags() {
     return;
   }
 
-  dout(20) << dendl;
+  dout(15) << dendl;
   update_progress("GET_REMOTE_TAGS");
 
   Context *ctx = create_context_callback<
@@ -534,17 +536,17 @@ void BootstrapRequest<I>::get_remote_tags() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_get_remote_tags(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": failed to retrieve remote tags: " << cpp_strerror(r) << dendl;
+    derr << "failed to retrieve remote tags: " << cpp_strerror(r) << dendl;
     m_ret_val = r;
     close_local_image();
     return;
   }
 
   if (m_canceled) {
-    dout(10) << ": request canceled" << dendl;
+    dout(10) << "request canceled" << dendl;
     m_ret_val = -ECANCELED;
     close_local_image();
     return;
@@ -564,7 +566,7 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
     if (m_local_tag_data.predecessor.commit_valid &&
         m_local_tag_data.predecessor.mirror_uuid == m_remote_mirror_uuid &&
         m_local_tag_data.predecessor.tag_tid > remote_tag.tid) {
-      dout(15) << ": skipping processed predecessor remote tag "
+      dout(15) << "skipping processed predecessor remote tag "
                << remote_tag.tid << dendl;
       continue;
     }
@@ -574,24 +576,24 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
       decode(remote_tag_data, it);
       remote_tag_data_valid = true;
     } catch (const buffer::error &err) {
-      derr << ": failed to decode remote tag " << remote_tag.tid << ": "
+      derr << "failed to decode remote tag " << remote_tag.tid << ": "
            << err.what() << dendl;
       m_ret_val = -EBADMSG;
       close_local_image();
       return;
     }
 
-    dout(10) << ": decoded remote tag " << remote_tag.tid << ": "
+    dout(10) << "decoded remote tag " << remote_tag.tid << ": "
              << remote_tag_data << dendl;
 
     if (!m_local_tag_data.predecessor.commit_valid) {
       // newly synced local image (no predecessor) replays from the first tag
       if (remote_tag_data.mirror_uuid != librbd::Journal<>::LOCAL_MIRROR_UUID) {
-        dout(15) << ": skipping non-primary remote tag" << dendl;
+        dout(15) << "skipping non-primary remote tag" << dendl;
         continue;
       }
 
-      dout(10) << ": using initial primary remote tag" << dendl;
+      dout(10) << "using initial primary remote tag" << dendl;
       break;
     }
 
@@ -608,7 +610,7 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
             m_local_tag_data.predecessor.mirror_uuid ==
               librbd::Journal<>::LOCAL_MIRROR_UUID) {
           // local demoted and remote has matching event
-          dout(15) << ": found matching local demotion tag" << dendl;
+          dout(15) << "found matching local demotion tag" << dendl;
           remote_orphan_tag_tid = remote_tag.tid;
           continue;
         }
@@ -617,7 +619,7 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
             remote_tag_data.predecessor.mirror_uuid ==
               librbd::Journal<>::LOCAL_MIRROR_UUID) {
           // remote demoted and local has matching event
-          dout(15) << ": found matching remote demotion tag" << dendl;
+          dout(15) << "found matching remote demotion tag" << dendl;
           remote_orphan_tag_tid = remote_tag.tid;
           continue;
         }
@@ -628,7 +630,7 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
           remote_tag_data.predecessor.commit_valid && remote_orphan_tag_tid &&
           remote_tag_data.predecessor.tag_tid == *remote_orphan_tag_tid) {
         // remote promotion tag chained to remote/local demotion tag
-        dout(15) << ": found chained remote promotion tag" << dendl;
+        dout(15) << "found chained remote promotion tag" << dendl;
         reconnect_orphan = true;
         break;
       }
@@ -640,11 +642,11 @@ void BootstrapRequest<I>::handle_get_remote_tags(int r) {
 
   if (remote_tag_data_valid &&
       m_local_tag_data.mirror_uuid == m_remote_mirror_uuid) {
-    dout(10) << ": local image is in clean replay state" << dendl;
+    dout(10) << "local image is in clean replay state" << dendl;
   } else if (reconnect_orphan) {
-    dout(10) << ": remote image was demoted/promoted" << dendl;
+    dout(10) << "remote image was demoted/promoted" << dendl;
   } else {
-    derr << ": split-brain detected -- skipping image replay" << dendl;
+    derr << "split-brain detected -- skipping image replay" << dendl;
     m_ret_val = -EEXIST;
     close_local_image();
     return;
@@ -661,12 +663,12 @@ void BootstrapRequest<I>::image_sync() {
     return;
   }
 
-  dout(20) << dendl;
   {
     Mutex::Locker locker(m_lock);
     if (m_canceled) {
       m_ret_val = -ECANCELED;
     } else {
+      dout(15) << dendl;
       ceph_assert(m_image_sync == nullptr);
 
       Context *ctx = create_context_callback<
@@ -688,13 +690,13 @@ void BootstrapRequest<I>::image_sync() {
     }
   }
 
-  dout(10) << ": request canceled" << dendl;
+  dout(10) << "request canceled" << dendl;
   close_remote_image();
 }
 
 template <typename I>
 void BootstrapRequest<I>::handle_image_sync(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   {
     Mutex::Locker locker(m_lock);
@@ -702,12 +704,12 @@ void BootstrapRequest<I>::handle_image_sync(int r) {
     m_image_sync = nullptr;
 
     if (m_canceled) {
-      dout(10) << ": request canceled" << dendl;
+      dout(10) << "request canceled" << dendl;
       m_ret_val = -ECANCELED;
     }
 
     if (r < 0) {
-      derr << ": failed to sync remote image: " << cpp_strerror(r) << dendl;
+      derr << "failed to sync remote image: " << cpp_strerror(r) << dendl;
       m_ret_val = r;
     }
   }
@@ -717,7 +719,7 @@ void BootstrapRequest<I>::handle_image_sync(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::close_local_image() {
-  dout(20) << dendl;
+  dout(15) << dendl;
 
   update_progress("CLOSE_LOCAL_IMAGE");
 
@@ -731,10 +733,10 @@ void BootstrapRequest<I>::close_local_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_close_local_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": error encountered closing local image: " << cpp_strerror(r)
+    derr << "error encountered closing local image: " << cpp_strerror(r)
          << dendl;
   }
 
@@ -743,7 +745,7 @@ void BootstrapRequest<I>::handle_close_local_image(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::close_remote_image() {
-  dout(20) << dendl;
+  dout(15) << dendl;
 
   update_progress("CLOSE_REMOTE_IMAGE");
 
@@ -757,10 +759,10 @@ void BootstrapRequest<I>::close_remote_image() {
 
 template <typename I>
 void BootstrapRequest<I>::handle_close_remote_image(int r) {
-  dout(20) << ": r=" << r << dendl;
+  dout(15) << "r=" << r << dendl;
 
   if (r < 0) {
-    derr << ": error encountered closing remote image: " << cpp_strerror(r)
+    derr << "error encountered closing remote image: " << cpp_strerror(r)
          << dendl;
   }
 
@@ -769,7 +771,7 @@ void BootstrapRequest<I>::handle_close_remote_image(int r) {
 
 template <typename I>
 void BootstrapRequest<I>::update_progress(const std::string &description) {
-  dout(20) << ": " << description << dendl;
+  dout(15) << description << dendl;
 
   if (m_progress_ctx) {
     m_progress_ctx->update_progress(description);