From: Jason Dillaman <dillaman@redhat.com>
Date: Tue, 24 Jan 2017 14:24:52 +0000 (-0500)
Subject: librbd: improve debug logging for lock / watch state machines
X-Git-Tag: v11.2.1~224^2
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=refs%2Fpull%2F13102%2Fhead;p=ceph.git

librbd: improve debug logging for lock / watch state machines

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

diff --git a/src/librbd/exclusive_lock/AcquireRequest.cc b/src/librbd/exclusive_lock/AcquireRequest.cc
index 5a495805deb..d9a75e46217 100644
--- a/src/librbd/exclusive_lock/AcquireRequest.cc
+++ b/src/librbd/exclusive_lock/AcquireRequest.cc
@@ -22,7 +22,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::exclusive_lock::AcquireRequest: "
+#define dout_prefix *_dout << "librbd::exclusive_lock::AcquireRequest: " \
+                           << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace exclusive_lock {
@@ -64,7 +65,7 @@ void AcquireRequest<I>::send() {
 template <typename I>
 void AcquireRequest<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<
@@ -75,7 +76,7 @@ void AcquireRequest<I>::send_prepare_lock() {
 template <typename I>
 Context *AcquireRequest<I>::handle_prepare_lock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   send_flush_notifies();
   return nullptr;
@@ -84,7 +85,7 @@ Context *AcquireRequest<I>::handle_prepare_lock(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_flush_notifies() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_flush_notifies>(
@@ -95,7 +96,7 @@ void AcquireRequest<I>::send_flush_notifies() {
 template <typename I>
 Context *AcquireRequest<I>::handle_flush_notifies(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   assert(*ret_val == 0);
   send_get_locker();
@@ -105,7 +106,7 @@ Context *AcquireRequest<I>::handle_flush_notifies(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_get_locker() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   Context *ctx = create_context_callback<
     AcquireRequest<I>, &AcquireRequest<I>::handle_get_locker>(this);
@@ -116,7 +117,7 @@ void AcquireRequest<I>::send_get_locker() {
 template <typename I>
 Context *AcquireRequest<I>::handle_get_locker(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == -ENOENT) {
     ldout(cct, 20) << "no lockers detected" << dendl;
@@ -138,7 +139,7 @@ Context *AcquireRequest<I>::handle_get_locker(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_lock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << "cookie=" << m_cookie << dendl;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::lock(&op, RBD_LOCK_NAME, LOCK_EXCLUSIVE, m_cookie,
@@ -156,7 +157,7 @@ void AcquireRequest<I>::send_lock() {
 template <typename I>
 Context *AcquireRequest<I>::handle_lock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == 0) {
     return send_refresh();
@@ -180,7 +181,7 @@ Context *AcquireRequest<I>::send_refresh() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_async_context_callback(
@@ -197,11 +198,11 @@ Context *AcquireRequest<I>::send_refresh() {
 template <typename I>
 Context *AcquireRequest<I>::handle_refresh(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == -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;
     *ret_val = 0;
   } else if (*ret_val < 0) {
     lderr(cct) << "failed to refresh image: " << cpp_strerror(*ret_val)
@@ -233,7 +234,7 @@ Context *AcquireRequest<I>::send_open_journal() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_open_journal>(
@@ -250,7 +251,7 @@ Context *AcquireRequest<I>::send_open_journal() {
 template <typename I>
 Context *AcquireRequest<I>::handle_open_journal(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     lderr(cct) << "failed to open journal: " << cpp_strerror(*ret_val) << dendl;
@@ -266,7 +267,7 @@ Context *AcquireRequest<I>::handle_open_journal(int *ret_val) {
 template <typename I>
 void AcquireRequest<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 = AcquireRequest<I>;
@@ -278,7 +279,7 @@ void AcquireRequest<I>::send_allocate_journal_tag() {
 template <typename I>
 Context *AcquireRequest<I>::handle_allocate_journal_tag(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     lderr(cct) << "failed to allocate journal tag: " << cpp_strerror(*ret_val)
@@ -293,7 +294,7 @@ Context *AcquireRequest<I>::handle_allocate_journal_tag(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_close_journal() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_close_journal>(
@@ -304,7 +305,7 @@ void AcquireRequest<I>::send_close_journal() {
 template <typename I>
 Context *AcquireRequest<I>::handle_close_journal(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     lderr(cct) << "failed to close journal: " << cpp_strerror(*ret_val)
@@ -322,7 +323,7 @@ Context *AcquireRequest<I>::send_open_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_open_object_map>(
@@ -336,7 +337,7 @@ Context *AcquireRequest<I>::send_open_object_map() {
 template <typename I>
 Context *AcquireRequest<I>::handle_open_object_map(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     lderr(cct) << "failed to open object map: " << cpp_strerror(*ret_val)
@@ -358,7 +359,7 @@ void AcquireRequest<I>::send_close_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = AcquireRequest<I>;
   Context *ctx = create_context_callback<
@@ -369,7 +370,7 @@ void AcquireRequest<I>::send_close_object_map() {
 template <typename I>
 Context *AcquireRequest<I>::handle_close_object_map(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   // object map should never result in an error
   assert(*ret_val == 0);
@@ -380,7 +381,7 @@ Context *AcquireRequest<I>::handle_close_object_map(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_unlock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::unlock(&op, RBD_LOCK_NAME, m_cookie);
@@ -397,7 +398,7 @@ void AcquireRequest<I>::send_unlock() {
 template <typename I>
 Context *AcquireRequest<I>::handle_unlock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     lderr(cct) << "failed to unlock image: " << cpp_strerror(*ret_val) << dendl;
@@ -410,7 +411,7 @@ Context *AcquireRequest<I>::handle_unlock(int *ret_val) {
 template <typename I>
 void AcquireRequest<I>::send_break_lock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   Context *ctx = create_context_callback<
     AcquireRequest<I>, &AcquireRequest<I>::handle_break_lock>(this);
@@ -422,7 +423,7 @@ void AcquireRequest<I>::send_break_lock() {
 template <typename I>
 Context *AcquireRequest<I>::handle_break_lock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == -EAGAIN) {
     ldout(cct, 5) << "lock owner is still alive" << dendl;
diff --git a/src/librbd/exclusive_lock/ReleaseRequest.cc b/src/librbd/exclusive_lock/ReleaseRequest.cc
index c37cbc86456..fbe2854fbf4 100644
--- a/src/librbd/exclusive_lock/ReleaseRequest.cc
+++ b/src/librbd/exclusive_lock/ReleaseRequest.cc
@@ -16,7 +16,8 @@
 
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
-#define dout_prefix *_dout << "librbd::exclusive_lock::ReleaseRequest: "
+#define dout_prefix *_dout << "librbd::exclusive_lock::ReleaseRequest: " \
+                           << this << " " << __func__ << ": "
 
 namespace librbd {
 namespace exclusive_lock {
@@ -65,7 +66,7 @@ void ReleaseRequest<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<
@@ -76,7 +77,7 @@ void ReleaseRequest<I>::send_prepare_lock() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_prepare_lock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   send_cancel_op_requests();
   return nullptr;
@@ -85,7 +86,7 @@ Context *ReleaseRequest<I>::handle_prepare_lock(int *ret_val) {
 template <typename I>
 void ReleaseRequest<I>::send_cancel_op_requests() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = ReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -96,7 +97,7 @@ void ReleaseRequest<I>::send_cancel_op_requests() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_cancel_op_requests(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   assert(*ret_val == 0);
 
@@ -107,7 +108,7 @@ Context *ReleaseRequest<I>::handle_cancel_op_requests(int *ret_val) {
 template <typename I>
 void ReleaseRequest<I>::send_block_writes() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = ReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -125,7 +126,7 @@ void ReleaseRequest<I>::send_block_writes() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_block_writes(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == -EBLACKLISTED) {
     // allow clean shut down if blacklisted
@@ -149,7 +150,7 @@ void ReleaseRequest<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(
@@ -162,7 +163,7 @@ void ReleaseRequest<I>::send_invalidate_cache(bool purge_on_error) {
 template <typename I>
 Context *ReleaseRequest<I>::handle_invalidate_cache(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val == -EBLACKLISTED) {
     lderr(cct) << "failed to invalidate cache because client is blacklisted"
@@ -186,7 +187,7 @@ Context *ReleaseRequest<I>::handle_invalidate_cache(int *ret_val) {
 template <typename I>
 void ReleaseRequest<I>::send_flush_notifies() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = ReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -197,7 +198,7 @@ void ReleaseRequest<I>::send_flush_notifies() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_flush_notifies(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   assert(*ret_val == 0);
   send_close_journal();
@@ -217,7 +218,7 @@ void ReleaseRequest<I>::send_close_journal() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = ReleaseRequest<I>;
   Context *ctx = create_context_callback<klass, &klass::handle_close_journal>(
@@ -228,7 +229,7 @@ void ReleaseRequest<I>::send_close_journal() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_close_journal(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0) {
     // error implies some journal events were not flushed -- continue
@@ -255,7 +256,7 @@ void ReleaseRequest<I>::send_close_object_map() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << dendl;
 
   using klass = ReleaseRequest<I>;
   Context *ctx = create_context_callback<
@@ -266,7 +267,7 @@ void ReleaseRequest<I>::send_close_object_map() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_close_object_map(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   // object map shouldn't return errors
   assert(*ret_val == 0);
@@ -279,7 +280,7 @@ Context *ReleaseRequest<I>::handle_close_object_map(int *ret_val) {
 template <typename I>
 void ReleaseRequest<I>::send_unlock() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << dendl;
+  ldout(cct, 10) << "cookie=" << m_cookie << dendl;
 
   if (m_on_releasing != nullptr) {
     // alert caller that we no longer own the exclusive lock
@@ -302,7 +303,7 @@ void ReleaseRequest<I>::send_unlock() {
 template <typename I>
 Context *ReleaseRequest<I>::handle_unlock(int *ret_val) {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << __func__ << ": r=" << *ret_val << dendl;
+  ldout(cct, 10) << "r=" << *ret_val << dendl;
 
   if (*ret_val < 0 && *ret_val != -ENOENT) {
     lderr(cct) << "failed to unlock: " << cpp_strerror(*ret_val) << dendl;
diff --git a/src/librbd/image_watcher/RewatchRequest.cc b/src/librbd/image_watcher/RewatchRequest.cc
index cbf22c07087..3a7daf76851 100644
--- a/src/librbd/image_watcher/RewatchRequest.cc
+++ b/src/librbd/image_watcher/RewatchRequest.cc
@@ -10,7 +10,7 @@
 #define dout_subsys ceph_subsys_rbd
 #undef dout_prefix
 #define dout_prefix *_dout << "librbd::image_watcher::RewatchRequest: " \
-                           << this << ": " << __func__
+                           << this << " " << __func__ << " "
 
 namespace librbd {
 namespace image_watcher {