librbd: improve debugging output for ImageWatcher

Include the instance pointer so that different images
can be differentiated in the logs.

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

diff --git a/src/librbd/ImageWatcher.cc b/src/librbd/ImageWatcher.cc
index 6cfa6d7c5626ca675652d98b1e280b3174679bfe..78cbd28d88f0f3f8a2edfaaee09cdd0a65222227 100644 (file)
--- a/src/librbd/ImageWatcher.cc
+++ b/src/librbd/ImageWatcher.cc
@@ -75,7 +75,7 @@ bool ImageWatcher::is_lock_owner() const {
 }
 
 int ImageWatcher::register_watch() {
-  ldout(m_image_ctx.cct, 10) << "registering image watcher" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " registering image watcher" << dendl;
 
   RWLock::WLocker l(m_watch_lock);
   assert(m_watch_state == WATCH_STATE_UNREGISTERED);
@@ -91,7 +91,7 @@ int ImageWatcher::register_watch() {
 }
 
 int ImageWatcher::unregister_watch() {
-  ldout(m_image_ctx.cct, 10)  << "unregistering image watcher" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " unregistering image watcher" << dendl;
 
   {
     Mutex::Locker l(m_aio_request_lock);
@@ -152,25 +152,26 @@ int ImageWatcher::try_lock() {
                    iter->addr, sizeof(iter->addr)) == 0) &&
          (locker_handle == iter->cookie)) {
        Mutex::Locker l(m_owner_client_id_lock);
-       m_owner_client_id = ClientId(iter->watcher_id, locker_handle);
+        set_owner_client_id(ClientId(iter->watcher_id, locker_handle));
        return 0;
       }
     }
 
     if (m_image_ctx.blacklist_on_break_lock) {
-      ldout(m_image_ctx.cct, 1) << "blacklisting client: " << locker << "@"
-                               << locker_address << dendl;
+      ldout(m_image_ctx.cct, 1) << this << " blacklisting client: " << locker
+                                << "@" << locker_address << dendl;
       librados::Rados rados(m_image_ctx.md_ctx);
       r = rados.blacklist_add(locker_address,
                              m_image_ctx.blacklist_expire_seconds);
       if (r < 0) {
-        lderr(m_image_ctx.cct) << "unable to blacklist client: "
+        lderr(m_image_ctx.cct) << this << " unable to blacklist client: "
                               << cpp_strerror(r) << dendl;
         return r;
       }
     }
 
-    ldout(m_image_ctx.cct, 5) << "breaking exclusive lock: " << locker << dendl;
+    ldout(m_image_ctx.cct, 5) << this << " breaking exclusive lock: " << locker
+                              << dendl;
     r = rados::cls::lock::break_lock(&m_image_ctx.md_ctx,
                                      m_image_ctx.header_oid, RBD_LOCK_NAME,
                                      locker_cookie, locker);
@@ -189,7 +190,7 @@ void ImageWatcher::request_lock(
   {
     Mutex::Locker l(m_aio_request_lock);
     bool request_pending = !m_aio_requests.empty();
-    ldout(m_image_ctx.cct, 15) << "queuing aio request: " << c
+    ldout(m_image_ctx.cct, 15) << this << " queuing aio request: " << c
                               << dendl;
 
     c->get();
@@ -201,7 +202,7 @@ void ImageWatcher::request_lock(
 
   RWLock::RLocker l(m_watch_lock);
   if (m_watch_state == WATCH_STATE_REGISTERED) {
-    ldout(m_image_ctx.cct, 10) << "requesting exclusive lock" << dendl;
+    ldout(m_image_ctx.cct, 15) << this << " requesting exclusive lock" << dendl;
 
     // run notify request in finisher to avoid blocking aio path
     FunctionContext *ctx = new FunctionContext(
@@ -227,17 +228,18 @@ bool ImageWatcher::try_request_lock() {
   m_image_ctx.owner_lock.get_read();
 
   if (r < 0) {
-    ldout(m_image_ctx.cct, 5) << "failed to acquire exclusive lock:"
+    ldout(m_image_ctx.cct, 5) << this << " failed to acquire exclusive lock:"
                              << cpp_strerror(r) << dendl;
     return false;
   }
 
   if (is_lock_owner()) {
-    ldout(m_image_ctx.cct, 15) << "successfully acquired exclusive lock"
+    ldout(m_image_ctx.cct, 15) << this << " successfully acquired exclusive lock"
                               << dendl;
   } else {
-    ldout(m_image_ctx.cct, 15) << "unable to acquire exclusive lock, retrying"
-                              << dendl;
+    ldout(m_image_ctx.cct, 15) << this
+                               << " unable to acquire exclusive lock, retrying"
+                               << dendl;
   }
   return is_lock_owner();
 }
@@ -257,34 +259,34 @@ int ImageWatcher::get_lock_owner_info(entity_name_t *locker, std::string *cookie
   }
 
   if (lockers.empty()) {
-    ldout(m_image_ctx.cct, 20) << "no lockers detected" << dendl;
+    ldout(m_image_ctx.cct, 20) << this << " no lockers detected" << dendl;
     return 0;
   }
 
   if (lock_tag != WATCHER_LOCK_TAG) {
-    ldout(m_image_ctx.cct, 5) << "locked by external mechanism: tag="
+    ldout(m_image_ctx.cct, 5) << this << " locked by external mechanism: tag="
                              << lock_tag << dendl;
     return -EBUSY;
   }
 
   if (lock_type == LOCK_SHARED) {
-    ldout(m_image_ctx.cct, 5) << "shared lock type detected" << dendl;
+    ldout(m_image_ctx.cct, 5) << this << " shared lock type detected" << dendl;
     return -EBUSY;
   }
 
   std::map<rados::cls::lock::locker_id_t,
            rados::cls::lock::locker_info_t>::iterator iter = lockers.begin();
   if (!decode_lock_cookie(iter->first.cookie, handle)) {
-    ldout(m_image_ctx.cct, 5) << "locked by external mechanism: cookie="
-                             << iter->first.cookie << dendl;
+    ldout(m_image_ctx.cct, 5) << this << " locked by external mechanism: "
+                              << "cookie=" << iter->first.cookie << dendl;
     return -EBUSY;
   }
 
   *locker = iter->first.locker;
   *cookie = iter->first.cookie;
   *address = stringify(iter->second.addr);
-  ldout(m_image_ctx.cct, 10) << "retrieved exclusive locker: " << *locker
-                            << "@" << *address << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " retrieved exclusive locker: "
+                             << *locker << "@" << *address << dendl;
   return 0;
 }
 
@@ -297,13 +299,13 @@ int ImageWatcher::lock() {
     return r;
   }
 
-  ldout(m_image_ctx.cct, 10) << "acquired exclusive lock" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " acquired exclusive lock" << dendl;
   m_lock_owner_state = LOCK_OWNER_STATE_LOCKED;
 
   ClientId owner_client_id = get_client_id();
   {
     Mutex::Locker l(m_owner_client_id_lock);
-    m_owner_client_id = owner_client_id;
+    set_owner_client_id(owner_client_id);
   }
 
   if (m_image_ctx.object_map.enabled()) {
@@ -348,12 +350,12 @@ int ImageWatcher::unlock()
     return 0;
   }
 
-  ldout(m_image_ctx.cct, 10) << "releasing exclusive lock" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " releasing exclusive lock" << dendl;
   m_lock_owner_state = LOCK_OWNER_STATE_NOT_LOCKED;
   int r = rados::cls::lock::unlock(&m_image_ctx.md_ctx, m_image_ctx.header_oid,
                                   RBD_LOCK_NAME, encode_lock_cookie());
   if (r < 0 && r != -ENOENT) {
-    lderr(m_image_ctx.cct) << "failed to release exclusive lock: "
+    lderr(m_image_ctx.cct) << this << " failed to release exclusive lock: "
                           << cpp_strerror(r) << dendl;
     return r;
   }
@@ -362,6 +364,9 @@ int ImageWatcher::unlock()
     m_image_ctx.object_map.unlock();
   }
 
+  Mutex::Locker l(m_owner_client_id_lock);
+  set_owner_client_id(ClientId());
+
   FunctionContext *ctx = new FunctionContext(
     boost::bind(&ImageWatcher::notify_released_lock, this));
   m_task_finisher->queue(TASK_CODE_RELEASED_LOCK, ctx);
@@ -371,7 +376,8 @@ int ImageWatcher::unlock()
 bool ImageWatcher::release_lock()
 {
   assert(m_image_ctx.owner_lock.is_wlocked());
-  ldout(m_image_ctx.cct, 10) << "releasing exclusive lock by request" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " releasing exclusive lock by request"
+                             << dendl;
   if (!is_lock_owner()) {
     return false;
   }
@@ -410,7 +416,7 @@ void ImageWatcher::schedule_async_progress(const AsyncRequestId &request,
 
 int ImageWatcher::notify_async_progress(const AsyncRequestId &request,
                                        uint64_t offset, uint64_t total) {
-  ldout(m_image_ctx.cct, 20) << "remote async request progress: "
+  ldout(m_image_ctx.cct, 20) << this << " remote async request progress: "
                             << request << " @ " << offset
                             << "/" << total << dendl;
 
@@ -430,7 +436,7 @@ void ImageWatcher::schedule_async_complete(const AsyncRequestId &request,
 
 int ImageWatcher::notify_async_complete(const AsyncRequestId &request,
                                        int r) {
-  ldout(m_image_ctx.cct, 20) << "remote async request finished: "
+  ldout(m_image_ctx.cct, 20) << this << " remote async request finished: "
                             << request << " = " << r << dendl;
 
   bufferlist bl;
@@ -443,7 +449,7 @@ int ImageWatcher::notify_async_complete(const AsyncRequestId &request,
   int ret = m_image_ctx.md_ctx.notify2(m_image_ctx.header_oid, bl,
                                       NOTIFY_TIMEOUT, NULL);
   if (ret < 0) {
-    lderr(m_image_ctx.cct) << "failed to notify async complete: "
+    lderr(m_image_ctx.cct) << this << " failed to notify async complete: "
                           << cpp_strerror(ret) << dendl;
     if (ret == -ETIMEDOUT) {
       schedule_async_complete(request, r);
@@ -559,11 +565,12 @@ void ImageWatcher::retry_aio_requests() {
     lock_request_restarts.swap(m_aio_requests);
   }
 
-  ldout(m_image_ctx.cct, 15) << "retrying pending aio requests" << dendl;
+  ldout(m_image_ctx.cct, 15) << this << " retrying pending aio requests"
+                             << dendl;
   for (std::vector<AioRequest>::iterator iter = lock_request_restarts.begin();
        iter != lock_request_restarts.end(); ++iter) {
-    ldout(m_image_ctx.cct, 20) << "retrying aio request: " << iter->second
-                              << dendl;
+    ldout(m_image_ctx.cct, 20) << this << " retrying aio request: "
+                               << iter->second << dendl;
     iter->first(iter->second);
     iter->second->put();
   }
@@ -585,6 +592,13 @@ void ImageWatcher::cancel_async_requests() {
   m_async_requests.clear();
 }
 
+void ImageWatcher::set_owner_client_id(const WatchNotify::ClientId& client_id) {
+  assert(m_owner_client_id_lock.is_locked());
+  m_owner_client_id = client_id;
+  ldout(m_image_ctx.cct, 10) << this << " current lock owner: "
+                             << m_owner_client_id << dendl;
+}
+
 ClientId ImageWatcher::get_client_id() {
   RWLock::RLocker l(m_watch_lock);
   return ClientId(m_image_ctx.md_ctx.get_instance_id(), m_watch_handle);
@@ -596,14 +610,14 @@ void ImageWatcher::notify_release_lock() {
 }
 
 void ImageWatcher::notify_released_lock() {
-  ldout(m_image_ctx.cct, 10) << "notify released lock" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " notify released lock" << dendl;
   bufferlist bl;
   ::encode(NotifyMessage(ReleasedLockPayload(get_client_id())), bl);
   m_image_ctx.md_ctx.notify2(m_image_ctx.header_oid, bl, NOTIFY_TIMEOUT, NULL);
 }
 
 void ImageWatcher::notify_request_lock() {
-  ldout(m_image_ctx.cct, 10) << "notify request lock" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " notify request lock" << dendl;
   m_task_finisher->cancel(TASK_CODE_RETRY_AIO_REQUESTS);
 
   m_image_ctx.owner_lock.get_read();
@@ -620,11 +634,12 @@ void ImageWatcher::notify_request_lock() {
   m_image_ctx.owner_lock.put_read();
 
   if (r == -ETIMEDOUT) {
-    ldout(m_image_ctx.cct, 5) << "timed out requesting lock: retrying" << dendl;
+    ldout(m_image_ctx.cct, 5) << this << "timed out requesting lock: retrying"
+                              << dendl;
     retry_aio_requests();
   } else if (r < 0) {
-    lderr(m_image_ctx.cct) << "error requesting lock: " << cpp_strerror(r)
-                          << dendl;
+    lderr(m_image_ctx.cct) << this << " error requesting lock: "
+                           << cpp_strerror(r) << dendl;
     schedule_retry_aio_requests(true);
   } else {
     // lock owner acked -- but resend if we don't see them release the lock
@@ -647,7 +662,7 @@ int ImageWatcher::notify_lock_owner(bufferlist &bl) {
                                     &response_bl);
   m_image_ctx.owner_lock.get_read();
   if (r < 0 && r != -ETIMEDOUT) {
-    lderr(m_image_ctx.cct) << "lock owner notification failed: "
+    lderr(m_image_ctx.cct) << this << " lock owner notification failed: "
                           << cpp_strerror(r) << dendl;
     return r;
   }
@@ -659,7 +674,7 @@ int ImageWatcher::notify_lock_owner(bufferlist &bl) {
       bufferlist::iterator iter = response_bl.begin();
       ::decode(responses, iter);
     } catch (const buffer::error &err) {
-      lderr(m_image_ctx.cct) << "failed to decode response" << dendl;
+      lderr(m_image_ctx.cct) << this << " failed to decode response" << dendl;
       return -EINVAL;
     }
   }
@@ -669,7 +684,8 @@ int ImageWatcher::notify_lock_owner(bufferlist &bl) {
   for (responses_t::iterator i = responses.begin(); i != responses.end(); ++i) {
     if (i->second.length() > 0) {
       if (lock_owner_responded) {
-       lderr(m_image_ctx.cct) << "duplicate lock owners detected" << dendl;
+       lderr(m_image_ctx.cct) << this << " duplicate lock owners detected"
+                               << dendl;
        return -EIO;
       }
       lock_owner_responded = true;
@@ -678,7 +694,7 @@ int ImageWatcher::notify_lock_owner(bufferlist &bl) {
   }
 
   if (!lock_owner_responded) {
-    lderr(m_image_ctx.cct) << "no lock owners detected" << dendl;
+    lderr(m_image_ctx.cct) << this << " no lock owners detected" << dendl;
     return -ETIMEDOUT;
   }
 
@@ -710,7 +726,7 @@ void ImageWatcher::async_request_timed_out(const AsyncRequestId &id) {
   std::map<AsyncRequestId, AsyncRequest>::iterator it =
     m_async_requests.find(id);
   if (it != m_async_requests.end()) {
-    ldout(m_image_ctx.cct, 10) << "request timed-out: " << id << dendl;
+    ldout(m_image_ctx.cct, 10) << this << " request timed-out: " << id << dendl;
     it->second.first->complete(-ERESTART);
   }
 }
@@ -720,7 +736,8 @@ int ImageWatcher::notify_async_request(const AsyncRequestId &async_request_id,
                                       ProgressContext& prog_ctx) {
   assert(m_image_ctx.owner_lock.is_locked());
 
-  ldout(m_image_ctx.cct, 10) << "async request: " << async_request_id << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " async request: " << async_request_id
+                             << dendl;
 
   C_SaferCond ctx;
 
@@ -774,7 +791,7 @@ void ImageWatcher::cleanup_async_request(const AsyncRequestId& async_request_id,
 
 void ImageWatcher::handle_payload(const HeaderUpdatePayload &payload,
                                  bufferlist *out) {
-  ldout(m_image_ctx.cct, 10) << "image header updated" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " image header updated" << dendl;
 
   Mutex::Locker lictx(m_image_ctx.refresh_lock);
   ++m_image_ctx.refresh_seq;
@@ -783,7 +800,8 @@ void ImageWatcher::handle_payload(const HeaderUpdatePayload &payload,
 
 void ImageWatcher::handle_payload(const AcquiredLockPayload &payload,
                                   bufferlist *out) {
-  ldout(m_image_ctx.cct, 10) << "image exclusively locked announcement" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " image exclusively locked announcement"
+                             << dendl;
   m_task_finisher->cancel(TASK_CODE_REQUEST_LOCK);
   if (payload.client_id.is_valid()) {
     Mutex::Locker l(m_owner_client_id_lock);
@@ -791,7 +809,7 @@ void ImageWatcher::handle_payload(const AcquiredLockPayload &payload,
       // we already know that the remote client is the owner
       return;
     }
-    m_owner_client_id = payload.client_id;
+    set_owner_client_id(payload.client_id);
   }
 
   RWLock::RLocker l(m_image_ctx.owner_lock);
@@ -803,14 +821,17 @@ void ImageWatcher::handle_payload(const AcquiredLockPayload &payload,
 
 void ImageWatcher::handle_payload(const ReleasedLockPayload &payload,
                                   bufferlist *out) {
-  ldout(m_image_ctx.cct, 10) << "exclusive lock released" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " exclusive lock released" << dendl;
   m_task_finisher->cancel(TASK_CODE_REQUEST_LOCK);
   if (payload.client_id.is_valid()) {
     Mutex::Locker l(m_owner_client_id_lock);
     if (payload.client_id != m_owner_client_id) {
+      ldout(m_image_ctx.cct, 10) << this << " unexpected owner: "
+                                 << payload.client_id << " != "
+                                 << m_owner_client_id << dendl;
       return;
     }
-    m_owner_client_id = ClientId();
+    set_owner_client_id(ClientId());
   }
 
   RWLock::RLocker l(m_image_ctx.owner_lock);
@@ -822,7 +843,7 @@ void ImageWatcher::handle_payload(const ReleasedLockPayload &payload,
 
 void ImageWatcher::handle_payload(const RequestLockPayload &payload,
                                   bufferlist *out) {
-  ldout(m_image_ctx.cct, 10) << "exclusive lock requested" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " exclusive lock requested" << dendl;
   if (payload.client_id == get_client_id()) {
     return;
   }
@@ -837,10 +858,10 @@ void ImageWatcher::handle_payload(const RequestLockPayload &payload,
       if (!m_owner_client_id.is_valid()) {
        return;
       }
-      m_owner_client_id = ClientId();
     }
 
-    ldout(m_image_ctx.cct, 10) << "queuing release of exclusive lock" << dendl;
+    ldout(m_image_ctx.cct, 10) << this << " queuing release of exclusive lock"
+                               << dendl;
     FunctionContext *ctx = new FunctionContext(
       boost::bind(&ImageWatcher::notify_release_lock, this));
     m_task_finisher->queue(TASK_CODE_RELEASING_LOCK, ctx);
@@ -853,7 +874,7 @@ void ImageWatcher::handle_payload(const AsyncProgressPayload &payload,
   std::map<AsyncRequestId, AsyncRequest>::iterator req_it =
     m_async_requests.find(payload.async_request_id);
   if (req_it != m_async_requests.end()) {
-    ldout(m_image_ctx.cct, 20) << "request progress: "
+    ldout(m_image_ctx.cct, 20) << this << " request progress: "
                               << payload.async_request_id << " @ "
                               << payload.offset << "/" << payload.total
                               << dendl;
@@ -868,7 +889,7 @@ void ImageWatcher::handle_payload(const AsyncCompletePayload &payload,
   std::map<AsyncRequestId, AsyncRequest>::iterator req_it =
     m_async_requests.find(payload.async_request_id);
   if (req_it != m_async_requests.end()) {
-    ldout(m_image_ctx.cct, 10) << "request finished: "
+    ldout(m_image_ctx.cct, 10) << this << " request finished: "
                                << payload.async_request_id << "="
                               << payload.result << dendl;
     req_it->second.first->complete(payload.result);
@@ -886,11 +907,11 @@ void ImageWatcher::handle_payload(const FlattenPayload &payload,
     int r = prepare_async_request(payload.async_request_id, &new_request,
                                   &ctx, &prog_ctx);
     if (new_request) {
-      ldout(m_image_ctx.cct, 10) << "remote flatten request: "
+      ldout(m_image_ctx.cct, 10) << this << " remote flatten request: "
                                 << payload.async_request_id << dendl;
       r = librbd::async_flatten(&m_image_ctx, ctx, *prog_ctx);
       if (r < 0) {
-       lderr(m_image_ctx.cct) << "remove flatten request failed: "
+       lderr(m_image_ctx.cct) << this << " remove flatten request failed: "
                               << cpp_strerror(r) << dendl;
         cleanup_async_request(payload.async_request_id, ctx);
       }
@@ -910,12 +931,12 @@ void ImageWatcher::handle_payload(const ResizePayload &payload,
     int r = prepare_async_request(payload.async_request_id, &new_request,
                                   &ctx, &prog_ctx);
     if (new_request) {
-      ldout(m_image_ctx.cct, 10) << "remote resize request: "
+      ldout(m_image_ctx.cct, 10) << this << " remote resize request: "
                                 << payload.async_request_id << " "
                                 << payload.size << dendl;
       r = librbd::async_resize(&m_image_ctx, ctx, payload.size, *prog_ctx);
       if (r < 0) {
-       lderr(m_image_ctx.cct) << "remove resize request failed: "
+       lderr(m_image_ctx.cct) << this << " remove resize request failed: "
                               << cpp_strerror(r) << dendl;
         cleanup_async_request(payload.async_request_id, ctx);
       }
@@ -929,7 +950,7 @@ void ImageWatcher::handle_payload(const SnapCreatePayload &payload,
                                  bufferlist *out) {
   RWLock::RLocker l(m_image_ctx.owner_lock);
   if (m_lock_owner_state == LOCK_OWNER_STATE_LOCKED) {
-    ldout(m_image_ctx.cct, 10) << "remote snap_create request: "
+    ldout(m_image_ctx.cct, 10) << this << " remote snap_create request: "
                               << payload.snap_name << dendl;
     int r = librbd::snap_create_helper(&m_image_ctx, NULL,
                                        payload.snap_name.c_str());
@@ -942,7 +963,7 @@ void ImageWatcher::handle_payload(const SnapRemovePayload &payload,
                                  bufferlist *out) {
   RWLock::RLocker l(m_image_ctx.owner_lock);
   if (m_lock_owner_state == LOCK_OWNER_STATE_LOCKED) {
-    ldout(m_image_ctx.cct, 10) << "remote snap_remove request: "
+    ldout(m_image_ctx.cct, 10) << this << " remote snap_remove request: "
                               << payload.snap_name << dendl;
     int r = librbd::snap_remove_helper(&m_image_ctx, NULL,
                                        payload.snap_name.c_str());
@@ -961,11 +982,13 @@ void ImageWatcher::handle_payload(const RebuildObjectMapPayload& payload,
     int r = prepare_async_request(payload.async_request_id, &new_request,
                                   &ctx, &prog_ctx);
     if (new_request) {
-      ldout(m_image_ctx.cct, 10) << "remote rebuild object map request: "
+      ldout(m_image_ctx.cct, 10) << this
+                                 << " remote rebuild object map request: "
                                  << payload.async_request_id << dendl;
       r = librbd::async_rebuild_object_map(&m_image_ctx, ctx, *prog_ctx);
       if (r < 0) {
-        lderr(m_image_ctx.cct) << "remove rebuild object map request failed: "
+        lderr(m_image_ctx.cct) << this
+                               << " remove rebuild object map request failed: "
                                << cpp_strerror(r) << dendl;
         cleanup_async_request(payload.async_request_id, ctx);
       }
@@ -994,23 +1017,23 @@ void ImageWatcher::handle_notify(uint64_t notify_id, uint64_t handle,
       bufferlist::iterator iter = bl.begin();
       ::decode(notify_message, iter);
     } catch (const buffer::error &err) {
-      lderr(m_image_ctx.cct) << "error decoding image notification: "
+      lderr(m_image_ctx.cct) << this << " error decoding image notification: "
                             << err.what() << dendl;
       return;
     }
   }
 
   apply_visitor(HandlePayloadVisitor(this, notify_id, handle),
-               notify_message.payload); 
+               notify_message.payload);
 }
 
 void ImageWatcher::handle_error(uint64_t handle, int err) {
-  lderr(m_image_ctx.cct) << "image watch failed: " << handle << ", "
+  lderr(m_image_ctx.cct) << this << " image watch failed: " << handle << ", "
                          << cpp_strerror(err) << dendl;
 
   {
     Mutex::Locker l(m_owner_client_id_lock);
-    m_owner_client_id = ClientId();
+    set_owner_client_id(ClientId());
   }
 
   RWLock::WLocker l(m_watch_lock);
@@ -1030,7 +1053,7 @@ void ImageWatcher::acknowledge_notify(uint64_t notify_id, uint64_t handle,
 }
 
 void ImageWatcher::reregister_watch() {
-  ldout(m_image_ctx.cct, 10) << "re-registering image watch" << dendl;
+  ldout(m_image_ctx.cct, 10) << this << " re-registering image watch" << dendl;
 
   {
     RWLock::WLocker l(m_image_ctx.owner_lock);
@@ -1050,7 +1073,7 @@ void ImageWatcher::reregister_watch() {
       r = m_image_ctx.md_ctx.watch2(m_image_ctx.header_oid,
                                     &m_watch_handle, &m_watch_ctx);
       if (r < 0) {
-        lderr(m_image_ctx.cct) << "failed to re-register image watch: "
+        lderr(m_image_ctx.cct) << this << " failed to re-register image watch: "
                                << cpp_strerror(r) << dendl;
        if (r != -ESHUTDOWN) {
          FunctionContext *ctx = new FunctionContext(boost::bind(
@@ -1068,10 +1091,11 @@ void ImageWatcher::reregister_watch() {
     if (was_lock_owner) {
       r = try_lock();
       if (r == -EBUSY) {
-        ldout(m_image_ctx.cct, 5) << "lost image lock while re-registering "
-                                  << "image watch" << dendl;
+        ldout(m_image_ctx.cct, 5) << this << "lost image lock while "
+                                  << "re-registering image watch" << dendl;
       } else if (r < 0) {
-        lderr(m_image_ctx.cct) << "failed to lock image while re-registering "
+        lderr(m_image_ctx.cct) << this
+                               << "failed to lock image while re-registering "
                                << "image watch" << cpp_strerror(r) << dendl;
       }
     }

diff --git a/src/librbd/ImageWatcher.h b/src/librbd/ImageWatcher.h
index 73538148f2918e791c31686aaec2bdcccb4ab3d5..6ebeb9dfcb840719d1b2cba108f70123b53812e6 100644 (file)
--- a/src/librbd/ImageWatcher.h
+++ b/src/librbd/ImageWatcher.h
@@ -222,6 +222,7 @@ namespace librbd {
     void schedule_cancel_async_requests();
     void cancel_async_requests();
 
+    void set_owner_client_id(const WatchNotify::ClientId &client_id);
     WatchNotify::ClientId get_client_id();
 
     void notify_release_lock();

diff --git a/src/librbd/WatchNotifyTypes.cc b/src/librbd/WatchNotifyTypes.cc
index 7532816ca3851d803487f05abf3f0196e160bc39..6785864d8422aa5a212004e88afacddc3e389b34 100644 (file)
--- a/src/librbd/WatchNotifyTypes.cc
+++ b/src/librbd/WatchNotifyTypes.cc
@@ -423,6 +423,12 @@ std::ostream &operator<<(std::ostream &out,
   return out;
 }
 
+std::ostream &operator<<(std::ostream &out,
+                         const librbd::WatchNotify::ClientId &client_id) {
+  out << "[" << client_id.gid << "," << client_id.handle << "]";
+  return out;
+}
+
 std::ostream &operator<<(std::ostream &out,
                          const librbd::WatchNotify::AsyncRequestId &request) {
   out << "[" << request.client_id.gid << "," << request.client_id.handle << ","

diff --git a/src/librbd/WatchNotifyTypes.h b/src/librbd/WatchNotifyTypes.h
index 1e9d089e5f1d75eb3658fb7a4fe8bb3df3f9cec5..ac978ad874ff8e24a4a01a5c877898c51e0b7305 100644 (file)
--- a/src/librbd/WatchNotifyTypes.h
+++ b/src/librbd/WatchNotifyTypes.h
@@ -259,6 +259,8 @@ struct ResponseMessage {
 
 std::ostream &operator<<(std::ostream &out,
                          const librbd::WatchNotify::NotifyOp &op);
+std::ostream &operator<<(std::ostream &out,
+                         const librbd::WatchNotify::ClientId &client);
 std::ostream &operator<<(std::ostream &out,
                          const librbd::WatchNotify::AsyncRequestId &request);