librbd: improve debug logging for lock / watch state machines

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

diff --git a/src/librbd/exclusive_lock/PostAcquireRequest.cc b/src/librbd/exclusive_lock/PostAcquireRequest.cc
index 3e262e792910cf9696cfba6670124d26842fe469..fb6e4d4d3208a19137c920435fc6a2c7e272a42e 100644 (file)
--- a/src/librbd/exclusive_lock/PostAcquireRequest.cc
+++ b/src/librbd/exclusive_lock/PostAcquireRequest.cc
@@ -20,7 +20,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::exclusive_lock::PostAcquireRequest: "
+#define dout_prefix *_dout << "librbd::exclusive_lock::PostAcquireRequest: " \
+                           << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace exclusive_lock {
@@ -68,7 +69,7 @@ void PostAcquireRequest<I>::send_refresh() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PostAcquireRequest<I>;
   Context *ctx = create_async_context_callback(
@@ -84,11 +85,11 @@ void PostAcquireRequest<I>::send_refresh() {
 template <typename I>
 void PostAcquireRequest<I>::handle_refresh(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r == -ERESTART) {
     // next issued IO or op will (re)-refresh the image and shut down lock
-    ldout(cct, 5) << ": exclusive lock dynamically disabled" << dendl;
+    ldout(cct, 5) << "exclusive lock dynamically disabled" << dendl;
     r = 0;
   } else if (r < 0) {
     lderr(cct) << "failed to refresh image: " << cpp_strerror(r) << dendl;
@@ -121,7 +122,7 @@ void PostAcquireRequest<I>::send_open_journal() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PostAcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_open_journal>(
@@ -137,7 +138,7 @@ void PostAcquireRequest<I>::send_open_journal() {
 template <typename I>
 void PostAcquireRequest<I>::handle_open_journal(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   save_result(r);
   if (r < 0) {
@@ -152,7 +153,7 @@ void PostAcquireRequest<I>::handle_open_journal(int r) {
 template <typename I>
 void PostAcquireRequest<I>::send_allocate_journal_tag() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   RWLock::RLocker snap_locker(m_image_ctx.snap_lock);
   using klass = PostAcquireRequest<I>;
@@ -164,7 +165,7 @@ void PostAcquireRequest<I>::send_allocate_journal_tag() {
 template <typename I>
 void PostAcquireRequest<I>::handle_allocate_journal_tag(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   save_result(r);
   if (r < 0) {
@@ -180,7 +181,7 @@ void PostAcquireRequest<I>::handle_allocate_journal_tag(int r) {
 template <typename I>
 void PostAcquireRequest<I>::send_close_journal() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PostAcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_close_journal>(
@@ -191,7 +192,7 @@ void PostAcquireRequest<I>::send_close_journal() {
 template <typename I>
 void PostAcquireRequest<I>::handle_close_journal(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   save_result(r);
   if (r < 0) {
@@ -209,7 +210,7 @@ void PostAcquireRequest<I>::send_open_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PostAcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_open_object_map>(
@@ -222,7 +223,7 @@ void PostAcquireRequest<I>::send_open_object_map() {
 template <typename I>
 void PostAcquireRequest<I>::handle_open_object_map(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r < 0) {
     lderr(cct) << "failed to open object map: " << cpp_strerror(r) << dendl;
@@ -244,7 +245,7 @@ void PostAcquireRequest<I>::send_close_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PostAcquireRequest<I>;
   Context *ctx = create_context_callback<
@@ -255,7 +256,7 @@ void PostAcquireRequest<I>::send_close_object_map() {
 template <typename I>
 void PostAcquireRequest<I>::handle_close_object_map(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   // object map should never result in an error
   assert(r == 0);

diff --git a/src/librbd/exclusive_lock/PreAcquireRequest.cc b/src/librbd/exclusive_lock/PreAcquireRequest.cc
index 25ef4809b2ddf21191aa3da10236b8123e6f3d6c..7711e9e2ef3a0d38614216ea03e1d6c682f65cdb 100644 (file)
--- a/src/librbd/exclusive_lock/PreAcquireRequest.cc
+++ b/src/librbd/exclusive_lock/PreAcquireRequest.cc
@@ -11,7 +11,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::exclusive_lock::PreAcquireRequest: "
+#define dout_prefix *_dout << "librbd::exclusive_lock::PreAcquireRequest: " \
+                           << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace exclusive_lock {
@@ -47,7 +48,7 @@ void PreAcquireRequest<I>::send() {
 template <typename I>
 void PreAcquireRequest<I>::send_prepare_lock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   // acquire the lock if the image is not busy performing other actions
   Context *ctx = create_context_callback<
@@ -58,7 +59,7 @@ void PreAcquireRequest<I>::send_prepare_lock() {
 template <typename I>
 void PreAcquireRequest<I>::handle_prepare_lock(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   send_flush_notifies();
 }
@@ -66,7 +67,7 @@ void PreAcquireRequest<I>::handle_prepare_lock(int r) {
 template <typename I>
 void PreAcquireRequest<I>::send_flush_notifies() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreAcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_flush_notifies>(
@@ -77,7 +78,7 @@ void PreAcquireRequest<I>::send_flush_notifies() {
 template <typename I>
 void PreAcquireRequest<I>::handle_flush_notifies(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   assert(r == 0);
   finish();

diff --git a/src/librbd/exclusive_lock/PreReleaseRequest.cc b/src/librbd/exclusive_lock/PreReleaseRequest.cc
index 44f9821720114b71aae47a75bd14131fbe6c6217..6d3382dd699a7499e5e1fb3c426b6a14d3d605a7 100644 (file)
--- a/src/librbd/exclusive_lock/PreReleaseRequest.cc
+++ b/src/librbd/exclusive_lock/PreReleaseRequest.cc
@@ -14,7 +14,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::exclusive_lock::PreReleaseRequest: "
+#define dout_prefix *_dout << "librbd::exclusive_lock::PreReleaseRequest: " \
+                           << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace exclusive_lock {
@@ -58,7 +59,7 @@ void PreReleaseRequest<I>::send_prepare_lock() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   // release the lock if the image is not busy performing other actions
   Context *ctx = create_context_callback<
@@ -69,7 +70,7 @@ void PreReleaseRequest<I>::send_prepare_lock() {
 template <typename I>
 void PreReleaseRequest<I>::handle_prepare_lock(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   send_cancel_op_requests();
 }
@@ -77,7 +78,7 @@ void PreReleaseRequest<I>::handle_prepare_lock(int r) {
 template <typename I>
 void PreReleaseRequest<I>::send_cancel_op_requests() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -88,7 +89,7 @@ void PreReleaseRequest<I>::send_cancel_op_requests() {
 template <typename I>
 void PreReleaseRequest<I>::handle_cancel_op_requests(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   assert(r == 0);
 
@@ -98,7 +99,7 @@ void PreReleaseRequest<I>::handle_cancel_op_requests(int r) {
 template <typename I>
 void PreReleaseRequest<I>::send_block_writes() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -116,7 +117,7 @@ void PreReleaseRequest<I>::send_block_writes() {
 template <typename I>
 void PreReleaseRequest<I>::handle_block_writes(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r == -EBLACKLISTED) {
     // allow clean shut down if blacklisted
@@ -141,7 +142,7 @@ void PreReleaseRequest<I>::send_invalidate_cache(bool purge_on_error) {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": purge_on_error=" << purge_on_error << dendl;
+  ldout(cct, 10) << "purge_on_error=" << purge_on_error << dendl;
 
   RWLock::RLocker owner_lock(m_image_ctx.owner_lock);
   Context *ctx = create_async_context_callback(
@@ -154,7 +155,7 @@ void PreReleaseRequest<I>::send_invalidate_cache(bool purge_on_error) {
 template <typename I>
 void PreReleaseRequest<I>::handle_invalidate_cache(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r == -EBLACKLISTED) {
     lderr(cct) << "failed to invalidate cache because client is blacklisted"
@@ -179,7 +180,7 @@ void PreReleaseRequest<I>::handle_invalidate_cache(int r) {
 template <typename I>
 void PreReleaseRequest<I>::send_flush_notifies() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreReleaseRequest<I>;
   Context *ctx =
@@ -190,7 +191,7 @@ void PreReleaseRequest<I>::send_flush_notifies() {
 template <typename I>
 void PreReleaseRequest<I>::handle_flush_notifies(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   assert(r == 0);
   send_close_journal();
@@ -209,7 +210,7 @@ void PreReleaseRequest<I>::send_close_journal() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreReleaseRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_close_journal>(
@@ -220,7 +221,7 @@ void PreReleaseRequest<I>::send_close_journal() {
 template <typename I>
 void PreReleaseRequest<I>::handle_close_journal(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r < 0) {
     // error implies some journal events were not flushed -- continue
@@ -245,7 +246,7 @@ void PreReleaseRequest<I>::send_close_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = PreReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -256,7 +257,7 @@ void PreReleaseRequest<I>::send_close_object_map() {
 template <typename I>
 void PreReleaseRequest<I>::handle_close_object_map(int r) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   // object map shouldn't return errors
   assert(r == 0);
@@ -268,7 +269,7 @@ void PreReleaseRequest<I>::handle_close_object_map(int r) {
 template <typename I>
 void PreReleaseRequest<I>::send_unlock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   finish();
 }

diff --git a/src/librbd/managed_lock/AcquireRequest.cc b/src/librbd/managed_lock/AcquireRequest.cc
index b89f658275f4e6ca07be1c8d87583192c7399b3d..e5d9186ca382b4288fd38b09db76780f006b55b7 100644 (file)
--- a/src/librbd/managed_lock/AcquireRequest.cc
+++ b/src/librbd/managed_lock/AcquireRequest.cc
@@ -104,7 +104,7 @@ void AcquireRequest<I>::handle_get_locker(int r) {
 
 template <typename I>
 void AcquireRequest<I>::send_lock() {
-  ldout(m_cct, 10) << dendl;
+  ldout(m_cct, 10) << "cookie=" << m_cookie << dendl;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::lock(&op, RBD_LOCK_NAME,

diff --git a/src/librbd/managed_lock/ReleaseRequest.cc b/src/librbd/managed_lock/ReleaseRequest.cc
index 84446a770415a1f015b90168dfebb0e7e93a461f..bf2f5ae91af24657b88cc07047c5f1b604a39eb1 100644 (file)
--- a/src/librbd/managed_lock/ReleaseRequest.cc
+++ b/src/librbd/managed_lock/ReleaseRequest.cc
@@ -13,7 +13,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::managed_lock::ReleaseRequest: "
+#define dout_prefix *_dout << "librbd::managed_lock::ReleaseRequest: " \
+                            << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace managed_lock {
@@ -54,7 +55,7 @@ void ReleaseRequest<I>::send() {
 template <typename I>
 void ReleaseRequest<I>::send_unlock() {
   CephContext *cct = reinterpret_cast<CephContext *>(m_ioctx.cct());
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << "cookie=" << m_cookie << dendl;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::unlock(&op, RBD_LOCK_NAME, m_cookie);
@@ -70,7 +71,7 @@ void ReleaseRequest<I>::send_unlock() {
 template <typename I>
 void ReleaseRequest<I>::handle_unlock(int r) {
   CephContext *cct = reinterpret_cast<CephContext *>(m_ioctx.cct());
-  ldout(cct, 10) << __func__ << ": r=" << r << dendl;
+  ldout(cct, 10) << "r=" << r << dendl;
 
   if (r < 0 && r != -ENOENT) {
     lderr(cct) << "failed to unlock: " << cpp_strerror(r) << dendl;

diff --git a/src/librbd/watcher/RewatchRequest.cc b/src/librbd/watcher/RewatchRequest.cc
index 688106960a998957db00c3b6827959daf5e23203..406e22ec9f3449dfc212ca6581f17cb4873e02b4 100644 (file)
--- a/src/librbd/watcher/RewatchRequest.cc
+++ b/src/librbd/watcher/RewatchRequest.cc
@@ -9,7 +9,7 @@
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
 #define dout_prefix *_dout << "librbd::watcher::RewatchRequest: " \
-                           << this << ": " << __func__
+                           << this << " " << __func__ << " "
 
 namespace librbd {