librbd: improve debug logging for lock / watch state machines

Signed-off-by: Jason Dillaman <dillaman@redhat.com>
This commit is contained in:
Jason Dillaman 2017-01-24 09:48:43 -05:00
parent 2ed02f3cd5
commit d934aa2942
6 changed files with 44 additions and 40 deletions

View File

@ -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);

View File

@ -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();

View File

@ -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();
}

View File

@ -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,

View File

@ -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;

View File

@ -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 {