librbd: improve debug logging for create/clone state machines

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

diff --git a/src/librbd/image/CloneRequest.cc b/src/librbd/image/CloneRequest.cc
index 1b5470636dc0d7d87348175ebcf6bde0a5bb9c3c..0606aa0ab246582a6cfa5df00de0912fbb9e965f 100644 (file)
--- a/src/librbd/image/CloneRequest.cc
+++ b/src/librbd/image/CloneRequest.cc
@@ -223,7 +223,7 @@ void CloneRequest<I>::validate_parent() {
 
 template <typename I>
 void CloneRequest<I>::validate_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   if ((m_features & RBD_FEATURE_LAYERING) != RBD_FEATURE_LAYERING) {
     lderr(m_cct) << "cloning image must support layering" << dendl;
@@ -247,7 +247,7 @@ void CloneRequest<I>::validate_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_validate_child(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r != -ENOENT) {
     lderr(m_cct) << "rbd image " << m_name << " already exists" << dendl;
@@ -261,7 +261,7 @@ void CloneRequest<I>::handle_validate_child(int r) {
 
 template <typename I>
 void CloneRequest<I>::create_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   uint64_t order = m_parent_image_ctx->order;
   if (m_opts.get(RBD_IMAGE_OPTION_ORDER, &order) != 0) {
@@ -282,7 +282,7 @@ void CloneRequest<I>::create_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_create_child(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r == -EBADF) {
     ldout(m_cct, 5) << "image id already in-use" << dendl;
@@ -299,7 +299,7 @@ void CloneRequest<I>::handle_create_child(int r) {
 
 template <typename I>
 void CloneRequest<I>::open_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   m_imctx = I::create(m_name, "", nullptr, m_ioctx, false);
 
@@ -317,7 +317,7 @@ void CloneRequest<I>::open_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_open_child(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     m_imctx->destroy();
@@ -334,7 +334,7 @@ void CloneRequest<I>::handle_open_child(int r) {
 
 template <typename I>
 void CloneRequest<I>::attach_parent() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   auto ctx = create_context_callback<
     CloneRequest<I>, &CloneRequest<I>::handle_attach_parent>(this);
@@ -345,7 +345,7 @@ void CloneRequest<I>::attach_parent() {
 
 template <typename I>
 void CloneRequest<I>::handle_attach_parent(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "failed to attach parent: " << cpp_strerror(r) << dendl;
@@ -364,7 +364,7 @@ void CloneRequest<I>::v2_set_op_feature() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::op_features_set(&op, RBD_OPERATION_FEATURE_CLONE_CHILD,
@@ -379,7 +379,7 @@ void CloneRequest<I>::v2_set_op_feature() {
 
 template <typename I>
 void CloneRequest<I>::handle_v2_set_op_feature(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "failed to enable clone v2: " << cpp_strerror(r) << dendl;
@@ -393,7 +393,7 @@ void CloneRequest<I>::handle_v2_set_op_feature(int r) {
 
 template <typename I>
 void CloneRequest<I>::v2_child_attach() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::child_attach(&op, m_parent_image_ctx->snap_id,
@@ -410,7 +410,7 @@ void CloneRequest<I>::v2_child_attach() {
 
 template <typename I>
 void CloneRequest<I>::handle_v2_child_attach(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "failed to attach child image: " << cpp_strerror(r)
@@ -425,7 +425,7 @@ void CloneRequest<I>::handle_v2_child_attach(int r) {
 
 template <typename I>
 void CloneRequest<I>::v1_add_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::add_child(&op, m_pspec, m_id);
@@ -440,7 +440,7 @@ void CloneRequest<I>::v1_add_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_v1_add_child(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "couldn't add child: " << cpp_strerror(r) << dendl;
@@ -454,7 +454,7 @@ void CloneRequest<I>::handle_v1_add_child(int r) {
 
 template <typename I>
 void CloneRequest<I>::v1_refresh() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CloneRequest<I>;
   RefreshRequest<I> *req = RefreshRequest<I>::create(
@@ -465,7 +465,7 @@ void CloneRequest<I>::v1_refresh() {
 
 template <typename I>
 void CloneRequest<I>::handle_v1_refresh(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   bool snap_protected = false;
   if (r == 0) {
@@ -485,8 +485,7 @@ void CloneRequest<I>::handle_v1_refresh(int r) {
 
 template <typename I>
 void CloneRequest<I>::metadata_list() {
-  ldout(m_cct, 20) << ": "
-                   << "start_key=" << m_last_metadata_key << dendl;
+  ldout(m_cct, 15) << "start_key=" << m_last_metadata_key << dendl;
 
   librados::ObjectReadOperation op;
   cls_client::metadata_list_start(&op, m_last_metadata_key, 0);
@@ -502,7 +501,7 @@ void CloneRequest<I>::metadata_list() {
 
 template <typename I>
 void CloneRequest<I>::handle_metadata_list(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   map<string, bufferlist> metadata;
   if (r == 0) {
@@ -541,7 +540,7 @@ void CloneRequest<I>::metadata_set() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::metadata_set(&op, m_pairs);
@@ -556,7 +555,7 @@ void CloneRequest<I>::metadata_set() {
 
 template <typename I>
 void CloneRequest<I>::handle_metadata_set(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "couldn't set metadata: " << cpp_strerror(r) << dendl;
@@ -569,7 +568,7 @@ void CloneRequest<I>::handle_metadata_set(int r) {
 
 template <typename I>
 void CloneRequest<I>::get_mirror_mode() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   if (!m_imctx->test_features(RBD_FEATURE_JOURNALING)) {
     close_child();
@@ -590,7 +589,7 @@ void CloneRequest<I>::get_mirror_mode() {
 
 template <typename I>
 void CloneRequest<I>::handle_get_mirror_mode(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r == 0) {
     auto it = m_out_bl.cbegin();
@@ -615,7 +614,7 @@ void CloneRequest<I>::handle_get_mirror_mode(int r) {
 
 template <typename I>
 void CloneRequest<I>::enable_mirror() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CloneRequest<I>;
   Context *ctx = create_context_callback<
@@ -629,7 +628,7 @@ void CloneRequest<I>::enable_mirror() {
 
 template <typename I>
 void CloneRequest<I>::handle_enable_mirror(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "failed to enable mirroring: " << cpp_strerror(r)
@@ -641,7 +640,7 @@ void CloneRequest<I>::handle_enable_mirror(int r) {
 
 template <typename I>
 void CloneRequest<I>::close_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   ceph_assert(m_imctx != nullptr);
 
@@ -654,7 +653,7 @@ void CloneRequest<I>::close_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_close_child(int r) {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   m_imctx->destroy();
   m_imctx = nullptr;
@@ -676,7 +675,7 @@ void CloneRequest<I>::handle_close_child(int r) {
 
 template <typename I>
 void CloneRequest<I>::remove_child() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CloneRequest<I>;
   Context *ctx = create_context_callback<
@@ -689,7 +688,7 @@ void CloneRequest<I>::remove_child() {
 
 template <typename I>
 void CloneRequest<I>::handle_remove_child(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "Error removing failed clone: "
@@ -730,11 +729,7 @@ void CloneRequest<I>::handle_close_parent(int r) {
 
 template <typename I>
 void CloneRequest<I>::complete(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
-
-  if (r == 0) {
-    ldout(m_cct, 20) << "done." << dendl;
-  }
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   m_on_finish->complete(r);
   delete this;

diff --git a/src/librbd/image/CreateRequest.cc b/src/librbd/image/CreateRequest.cc
index 54896aa2b63c3aae9b8abd54ec0a570f4bca6f07..693b95bb26d8069b92a0b150fe4fa6e544256f72 100644 (file)
--- a/src/librbd/image/CreateRequest.cc
+++ b/src/librbd/image/CreateRequest.cc
@@ -279,7 +279,7 @@ void CreateRequest<I>::handle_get_pool_metadata(int r) {
     m_features &= ~RBD_FEATURE_STRIPINGV2;
   }
 
-  ldout(m_cct, 20) << "name=" << m_image_name << ", "
+  ldout(m_cct, 10) << "name=" << m_image_name << ", "
                    << "id=" << m_image_id << ", "
                    << "size=" << m_size << ", "
                    << "features=" << m_features << ", "
@@ -339,7 +339,7 @@ void CreateRequest<I>::handle_get_pool_metadata(int r) {
 
 template <typename I>
 void CreateRequest<I>::validate_data_pool() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   librados::AioCompletion *comp =
@@ -356,7 +356,7 @@ void CreateRequest<I>::validate_data_pool() {
 
 template <typename I>
 void CreateRequest<I>::handle_validate_data_pool(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   bufferlist bl;
   bl.append("overwrite validated");
@@ -424,7 +424,7 @@ void CreateRequest<I>::handle_validate_data_pool(int r) {
 
 template<typename I>
 void CreateRequest<I>::add_image_to_directory() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   if (!m_io_ctx.get_namespace().empty()) {
@@ -442,7 +442,7 @@ void CreateRequest<I>::add_image_to_directory() {
 
 template<typename I>
 void CreateRequest<I>::handle_add_image_to_directory(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r == -EEXIST) {
     ldout(m_cct, 5) << "directory entry for image " << m_image_name
@@ -466,7 +466,7 @@ void CreateRequest<I>::handle_add_image_to_directory(int r) {
 
 template<typename I>
 void CreateRequest<I>::create_id_object() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   op.create(true);
@@ -482,7 +482,7 @@ void CreateRequest<I>::create_id_object() {
 
 template<typename I>
 void CreateRequest<I>::handle_create_id_object(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r == -EEXIST) {
     ldout(m_cct, 5) << "id object for  " << m_image_name << " already exists"
@@ -508,7 +508,7 @@ void CreateRequest<I>::negotiate_features() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectReadOperation op;
   cls_client::get_all_features_start(&op);
@@ -525,7 +525,7 @@ void CreateRequest<I>::negotiate_features() {
 
 template<typename I>
 void CreateRequest<I>::handle_negotiate_features(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   uint64_t all_features;
   if (r >= 0) {
@@ -546,7 +546,7 @@ void CreateRequest<I>::handle_negotiate_features(int r) {
 
 template<typename I>
 void CreateRequest<I>::create_image() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
   ceph_assert(m_data_pool.empty() || m_data_pool_id != -1);
 
   ostringstream oss;
@@ -577,7 +577,7 @@ void CreateRequest<I>::create_image() {
 
 template<typename I>
 void CreateRequest<I>::handle_create_image(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r == -EEXIST) {
     ldout(m_cct, 5) << "image id already in-use" << dendl;
@@ -601,7 +601,7 @@ void CreateRequest<I>::set_stripe_unit_count() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::set_stripe_unit_count(&op, m_stripe_unit, m_stripe_count);
@@ -616,7 +616,7 @@ void CreateRequest<I>::set_stripe_unit_count() {
 
 template<typename I>
 void CreateRequest<I>::handle_set_stripe_unit_count(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error setting stripe unit/count: "
@@ -636,7 +636,7 @@ void CreateRequest<I>::object_map_resize() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::object_map_resize(&op, Striper::get_num_objects(m_layout, m_size),
@@ -652,7 +652,7 @@ void CreateRequest<I>::object_map_resize() {
 
 template<typename I>
 void CreateRequest<I>::handle_object_map_resize(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error creating initial object map: "
@@ -673,7 +673,7 @@ void CreateRequest<I>::fetch_mirror_mode() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectReadOperation op;
   cls_client::mirror_mode_get_start(&op);
@@ -689,7 +689,7 @@ void CreateRequest<I>::fetch_mirror_mode() {
 
 template<typename I>
 void CreateRequest<I>::handle_fetch_mirror_mode(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if ((r < 0) && (r != -ENOENT)) {
     lderr(m_cct) << "failed to retrieve mirror mode: " << cpp_strerror(r)
@@ -733,7 +733,7 @@ void CreateRequest<I>::handle_fetch_mirror_mode(int r) {
 
 template<typename I>
 void CreateRequest<I>::journal_create() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_journal_create>(
@@ -753,7 +753,7 @@ void CreateRequest<I>::journal_create() {
 
 template<typename I>
 void CreateRequest<I>::handle_journal_create(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error creating journal: " << cpp_strerror(r)
@@ -775,7 +775,7 @@ void CreateRequest<I>::mirror_image_enable() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
   auto ctx = create_context_callback<
     CreateRequest<I>, &CreateRequest<I>::handle_mirror_image_enable>(this);
   auto req = mirror::EnableRequest<I>::create(m_io_ctx, m_image_id,
@@ -786,7 +786,7 @@ void CreateRequest<I>::mirror_image_enable() {
 
 template<typename I>
 void CreateRequest<I>::handle_mirror_image_enable(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "cannot enable mirroring: " << cpp_strerror(r)
@@ -802,11 +802,7 @@ void CreateRequest<I>::handle_mirror_image_enable(int r) {
 
 template<typename I>
 void CreateRequest<I>::complete(int r) {
-  ldout(m_cct, 20) << dendl;
-
-  if (r == 0) {
-    ldout(m_cct, 20) << "done." << dendl;
-  }
+  ldout(m_cct, 10) << "r=" << r << dendl;
 
   m_data_io_ctx.close();
   auto on_finish = m_on_finish;
@@ -822,7 +818,7 @@ void CreateRequest<I>::journal_remove() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_journal_remove>(
@@ -837,7 +833,7 @@ void CreateRequest<I>::journal_remove() {
 
 template<typename I>
 void CreateRequest<I>::handle_journal_remove(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error cleaning up journal after creation failed: "
@@ -854,7 +850,7 @@ void CreateRequest<I>::remove_object_map() {
     return;
   }
 
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   librados::AioCompletion *comp =
@@ -866,7 +862,7 @@ void CreateRequest<I>::remove_object_map() {
 
 template<typename I>
 void CreateRequest<I>::handle_remove_object_map(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error cleaning up object map after creation failed: "
@@ -878,7 +874,7 @@ void CreateRequest<I>::handle_remove_object_map(int r) {
 
 template<typename I>
 void CreateRequest<I>::remove_header_object() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   librados::AioCompletion *comp =
@@ -890,7 +886,7 @@ void CreateRequest<I>::remove_header_object() {
 
 template<typename I>
 void CreateRequest<I>::handle_remove_header_object(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error cleaning up image header after creation failed: "
@@ -902,7 +898,7 @@ void CreateRequest<I>::handle_remove_header_object(int r) {
 
 template<typename I>
 void CreateRequest<I>::remove_id_object() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   using klass = CreateRequest<I>;
   librados::AioCompletion *comp =
@@ -914,7 +910,7 @@ void CreateRequest<I>::remove_id_object() {
 
 template<typename I>
 void CreateRequest<I>::handle_remove_id_object(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error cleaning up id object after creation failed: "
@@ -926,7 +922,7 @@ void CreateRequest<I>::handle_remove_id_object(int r) {
 
 template<typename I>
 void CreateRequest<I>::remove_from_dir() {
-  ldout(m_cct, 20) << dendl;
+  ldout(m_cct, 15) << dendl;
 
   librados::ObjectWriteOperation op;
   cls_client::dir_remove_image(&op, m_image_name, m_image_id);
@@ -941,7 +937,7 @@ void CreateRequest<I>::remove_from_dir() {
 
 template<typename I>
 void CreateRequest<I>::handle_remove_from_dir(int r) {
-  ldout(m_cct, 20) << "r=" << r << dendl;
+  ldout(m_cct, 15) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(m_cct) << "error cleaning up image from rbd_directory object "