From 157a03f8fda6f5e65ce3e2fba6084df8c3d2eb4a Mon Sep 17 00:00:00 2001 From: Jason Dillaman Date: Tue, 22 May 2018 14:58:48 -0400 Subject: [PATCH] librbd: improve debug logging for create/clone state machines Signed-off-by: Jason Dillaman --- src/librbd/image/CloneRequest.cc | 63 +++++++++++++--------------- src/librbd/image/CreateRequest.cc | 68 +++++++++++++++---------------- 2 files changed, 61 insertions(+), 70 deletions(-) diff --git a/src/librbd/image/CloneRequest.cc b/src/librbd/image/CloneRequest.cc index 1b5470636dc..0606aa0ab24 100644 --- a/src/librbd/image/CloneRequest.cc +++ b/src/librbd/image/CloneRequest.cc @@ -223,7 +223,7 @@ void CloneRequest::validate_parent() { template void CloneRequest::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::validate_child() { template void CloneRequest::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::handle_validate_child(int r) { template void CloneRequest::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::create_child() { template void CloneRequest::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::handle_create_child(int r) { template void CloneRequest::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::open_child() { template void CloneRequest::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::handle_open_child(int r) { template void CloneRequest::attach_parent() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; auto ctx = create_context_callback< CloneRequest, &CloneRequest::handle_attach_parent>(this); @@ -345,7 +345,7 @@ void CloneRequest::attach_parent() { template void CloneRequest::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::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::v2_set_op_feature() { template void CloneRequest::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::handle_v2_set_op_feature(int r) { template void CloneRequest::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::v2_child_attach() { template void CloneRequest::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::handle_v2_child_attach(int r) { template void CloneRequest::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::v1_add_child() { template void CloneRequest::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::handle_v1_add_child(int r) { template void CloneRequest::v1_refresh() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CloneRequest; RefreshRequest *req = RefreshRequest::create( @@ -465,7 +465,7 @@ void CloneRequest::v1_refresh() { template void CloneRequest::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::handle_v1_refresh(int r) { template void CloneRequest::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::metadata_list() { template void CloneRequest::handle_metadata_list(int r) { - ldout(m_cct, 20) << "r=" << r << dendl; + ldout(m_cct, 15) << "r=" << r << dendl; map metadata; if (r == 0) { @@ -541,7 +540,7 @@ void CloneRequest::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::metadata_set() { template void CloneRequest::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::handle_metadata_set(int r) { template void CloneRequest::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::get_mirror_mode() { template void CloneRequest::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::handle_get_mirror_mode(int r) { template void CloneRequest::enable_mirror() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CloneRequest; Context *ctx = create_context_callback< @@ -629,7 +628,7 @@ void CloneRequest::enable_mirror() { template void CloneRequest::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::handle_enable_mirror(int r) { template void CloneRequest::close_child() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; ceph_assert(m_imctx != nullptr); @@ -654,7 +653,7 @@ void CloneRequest::close_child() { template void CloneRequest::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::handle_close_child(int r) { template void CloneRequest::remove_child() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CloneRequest; Context *ctx = create_context_callback< @@ -689,7 +688,7 @@ void CloneRequest::remove_child() { template void CloneRequest::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::handle_close_parent(int r) { template void CloneRequest::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 54896aa2b63..693b95bb26d 100644 --- a/src/librbd/image/CreateRequest.cc +++ b/src/librbd/image/CreateRequest.cc @@ -279,7 +279,7 @@ void CreateRequest::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::handle_get_pool_metadata(int r) { template void CreateRequest::validate_data_pool() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; librados::AioCompletion *comp = @@ -356,7 +356,7 @@ void CreateRequest::validate_data_pool() { template void CreateRequest::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::handle_validate_data_pool(int r) { template void CreateRequest::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::add_image_to_directory() { template void CreateRequest::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::handle_add_image_to_directory(int r) { template void CreateRequest::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::create_id_object() { template void CreateRequest::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::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::negotiate_features() { template void CreateRequest::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::handle_negotiate_features(int r) { template void CreateRequest::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::create_image() { template void CreateRequest::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::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::set_stripe_unit_count() { template void CreateRequest::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::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::object_map_resize() { template void CreateRequest::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::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::fetch_mirror_mode() { template void CreateRequest::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::handle_fetch_mirror_mode(int r) { template void CreateRequest::journal_create() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; Context *ctx = create_context_callback( @@ -753,7 +753,7 @@ void CreateRequest::journal_create() { template void CreateRequest::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::mirror_image_enable() { return; } - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; auto ctx = create_context_callback< CreateRequest, &CreateRequest::handle_mirror_image_enable>(this); auto req = mirror::EnableRequest::create(m_io_ctx, m_image_id, @@ -786,7 +786,7 @@ void CreateRequest::mirror_image_enable() { template void CreateRequest::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::handle_mirror_image_enable(int r) { template void CreateRequest::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::journal_remove() { return; } - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; Context *ctx = create_context_callback( @@ -837,7 +833,7 @@ void CreateRequest::journal_remove() { template void CreateRequest::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::remove_object_map() { return; } - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; librados::AioCompletion *comp = @@ -866,7 +862,7 @@ void CreateRequest::remove_object_map() { template void CreateRequest::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::handle_remove_object_map(int r) { template void CreateRequest::remove_header_object() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; librados::AioCompletion *comp = @@ -890,7 +886,7 @@ void CreateRequest::remove_header_object() { template void CreateRequest::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::handle_remove_header_object(int r) { template void CreateRequest::remove_id_object() { - ldout(m_cct, 20) << dendl; + ldout(m_cct, 15) << dendl; using klass = CreateRequest; librados::AioCompletion *comp = @@ -914,7 +910,7 @@ void CreateRequest::remove_id_object() { template void CreateRequest::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::handle_remove_id_object(int r) { template void CreateRequest::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::remove_from_dir() { template void CreateRequest::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 " -- 2.39.5