Merge pull request ceph#51852 from Matan-B/wip-matanb-crimson-watch-notify-logs

crimson/osd/watch: Add logs around Watch/Notify

Reviewed-by: Samuel Just <[email protected]>

Author: Matan-B

src/crimson/osd/watch.cc

@@ -111,7 +111,9 @@ seastar::future<> Watch::send_notify_msg(NotifyRef notify)
 
 seastar::future<> Watch::start_notify(NotifyRef notify)
 {
-  logger().info("{} adding notify(id={})", __func__, notify->ninfo.notify_id);
+  logger().debug("{} gid={} cookie={} starting notify(id={})",
+                 __func__,  get_watcher_gid(), get_cookie(),
+                 notify->ninfo.notify_id);
   auto [ it, emplaced ] = in_progress_notifies.emplace(std::move(notify));
   ceph_assert(emplaced);
   ceph_assert(is_alive());
@@ -158,6 +160,7 @@ seastar::future<> Watch::send_disconnect_msg()
 
 void Watch::discard_state()
 {
+  logger().debug("{} gid={} cookie={}", __func__, get_watcher_gid(), get_cookie());
   ceph_assert(obc);
   in_progress_notifies.clear();
   timeout_timer.cancel();
@@ -174,14 +177,18 @@ void Watch::got_ping(utime_t)
 
 seastar::future<> Watch::remove()
 {
-  logger().info("{}", __func__);
+  logger().debug("{} gid={} cookie={}", __func__, get_watcher_gid(), get_cookie());
   // in contrast to ceph-osd crimson sends CEPH_WATCH_EVENT_DISCONNECT directly
   // from the timeout handler and _after_ CEPH_WATCH_EVENT_NOTIFY_COMPLETE.
   // this simplifies the Watch::remove() interface as callers aren't obliged
   // anymore to decide whether EVENT_DISCONNECT needs to be send or not -- it
   // becomes an implementation detail of Watch.
   return seastar::do_for_each(in_progress_notifies,
     [this_shared=shared_from_this()] (auto notify) {
+      logger().debug("Watch::remove gid={} cookie={} notify(id={})",
+                     this_shared->get_watcher_gid(),
+                     this_shared->get_cookie(),
+                     notify->ninfo.notify_id);
       return notify->remove_watcher(this_shared);
     }).then([this] {
       discard_state();
@@ -191,7 +198,9 @@ seastar::future<> Watch::remove()
 
 void Watch::cancel_notify(const uint64_t notify_id)
 {
-  logger().info("{} notify_id={}", __func__, notify_id);
+  logger().debug("{} gid={} cookie={} notify(id={})",
+                 __func__,  get_watcher_gid(), get_cookie(),
+                 notify_id);
   const auto it = in_progress_notifies.find(notify_id);
   assert(it != std::end(in_progress_notifies));
   in_progress_notifies.erase(it);
@@ -222,8 +231,7 @@ bool notify_reply_t::operator<(const notify_reply_t& rhs) const
 std::ostream &operator<<(std::ostream &out, const notify_reply_t &rhs)
 {
   out << "notify_reply_t{watcher_gid=" << rhs.watcher_gid
-      << ", watcher_cookie=" << rhs.watcher_cookie
-      << ", bl=" << rhs.bl << "}";
+      << ", watcher_cookie=" << rhs.watcher_cookie << "}";
   return out;
 }
 
@@ -237,9 +245,19 @@ Notify::Notify(crimson::net::ConnectionRef conn,
     user_version(user_version)
 {}
 
+Notify::~Notify()
+{
+  logger().debug("{} for notify(id={})", __func__, ninfo.notify_id);
+}
+
 seastar::future<> Notify::remove_watcher(WatchRef watch)
 {
+  logger().debug("{} for notify(id={})", __func__, ninfo.notify_id);
+
   if (discarded || complete) {
+    logger().debug("{} for notify(id={}) discarded/complete already"
+                   " discarded: {} complete: {}", __func__,
+                   ninfo.notify_id, discarded ,complete);
     return seastar::now();
   }
   [[maybe_unused]] const auto num_removed = watchers.erase(watch);
@@ -259,7 +277,12 @@ seastar::future<> Notify::complete_watcher(
   WatchRef watch,
   const ceph::bufferlist& reply_bl)
 {
+  logger().debug("{} for notify(id={})", __func__, ninfo.notify_id);
+
   if (discarded || complete) {
+    logger().debug("{} for notify(id={}) discarded/complete already"
+                   " discarded: {} complete: {}", __func__,
+                   ninfo.notify_id, discarded ,complete);
     return seastar::now();
   }
   notify_replies.emplace(notify_reply_t{

src/crimson/osd/watch.h

@@ -140,6 +140,8 @@ class Notify : public seastar::enable_shared_from_this<Notify> {
     [this] { do_notify_timeout(); }
   };
 
+  ~Notify();
+
   /// (gid,cookie) -> reply_bl for everyone who acked the notify
   std::multiset<notify_reply_t> notify_replies;