]> git-server-git.apps.pok.os.sepia.ceph.com Git - ceph.git/commitdiff
test/osd: Improve test logging with OSD identification 68738/head
authorAlex Ainscow <aainscow@uk.ibm.com>
Sun, 3 May 2026 16:46:00 +0000 (17:46 +0100)
committerAlex Ainscow <aainscow@uk.ibm.com>
Mon, 8 Jun 2026 12:06:01 +0000 (13:06 +0100)
Modified the logging system to show which OSD is executing in test logs,
making it easier to debug multi-OSD test scenarios.

Changes:
- Added Log::set_prefix_hook() to allow tests to customize log prefixes
- Modified Log::_flush() to use prefix_hook when set, replacing thread IDs
- Added EventLoop::get_log_prefix() to return 'osd.X' or 'harness' based on context
- Updated EventLoop to track current_executing_osd during event execution
- Simplified PGBackendTestFixture to use NoDoutPrefix directly
- Removed redundant 'shard X:' prefix from ShardDpp (info already in PG identifier)
- Removed verbose console output from EventLoop (now redundant with OSD prefixes)
- Converted EventLoop message scheduling to use dout at level 20

Benefits:
- Test logs now show 'osd.X' instead of thread IDs during event execution
- Shows 'harness' for test setup/teardown code outside events
- Message scheduling visible in logs at debug level 20
- Makes multi-OSD test scenarios much easier to follow and debug
- No changes to production logging code

AI assisted code, with careful human review and checking.

AI-assisted-by: IBM Bob IDE:Claude Sonnet (Anthropic)
Signed-off-by: Alex Ainscow <aainscow@uk.ibm.com>
src/log/Log.cc
src/log/Log.h
src/test/osd/ECPeeringTestFixture.cc
src/test/osd/EventLoop.h
src/test/osd/PGBackendTestFixture.h

index 989438abbfdcd070eaee629dfb42716cf37c4ab7..4a79f0def283e26913a90160c9eb19afc7b5743c 100644 (file)
@@ -40,6 +40,11 @@ namespace logging {
 
 static OnExitManager exit_callbacks;
 
+// Static hook for getting log prefix (set by tests).
+// NOTE: Not thread-safe. Intended for single-threaded unit test harnesses
+// and should be set once during startup.
+static Log::prefix_hook_t prefix_hook = nullptr;
+
 static void log_on_exit(void *p)
 {
   Log *l = *(Log **)p;
@@ -48,6 +53,11 @@ static void log_on_exit(void *p)
   delete (Log **)p;// Delete allocated pointer (not Log object, the pointer only!)
 }
 
+void Log::set_prefix_hook(prefix_hook_t hook)
+{
+  prefix_hook = hook;
+}
+
 Log::Log(const SubsystemMap *s)
   : m_indirect_this(nullptr),
     m_subs(s),
@@ -409,7 +419,15 @@ void Log::_flush(EntryVector& t, bool crash)
         used += (std::size_t)snprintf(pos + used, allocated - used, "%6ld> ", -(--len));
       }
       used += (std::size_t)append_time(stamp, pos + used, allocated - used);
-      used += (std::size_t)snprintf(pos + used, allocated - used, " %lx %2d ", (unsigned long)thread, prio);
+      
+      // In tests, replace thread ID with custom prefix (e.g., "osd.X" or "harness")
+      const char* prefix = prefix_hook ? prefix_hook() : nullptr;
+      if (prefix) {
+        used += (std::size_t)snprintf(pos + used, allocated - used, " %s %2d ", prefix, prio);
+      } else {
+        used += (std::size_t)snprintf(pos + used, allocated - used, " %lx %2d ", (unsigned long)thread, prio);
+      }
+      
       memcpy(pos + used, str.data(), str.size());
       used += str.size();
       pos[used] = '\0';
index 99b636eb13a4d38a5454f8f40e0a01d0e2c41b2b..226afbd78cacd79e3686790e2abd12018d27daf4 100644 (file)
@@ -35,6 +35,7 @@ class Log : private Thread
 {
 public:
   using Thread::is_started;
+  using prefix_hook_t = const char* (*)();
 
   Log(const SubsystemMap *s);
   ~Log() override;
@@ -81,6 +82,14 @@ public:
   void inject_segv();
   void reset_segv();
 
+  /**
+   * Set a hook to get the log prefix (replaces thread ID in log output).
+   *
+   * @note Not thread-safe. Must be called once during startup before any
+   *       logging occurs. Designed for single-threaded unit test harnesses only.
+   */
+  static void set_prefix_hook(prefix_hook_t hook);
+
 protected:
   using EntryVector = std::vector<ConcreteEntry>;
 
index 172aa9a8dfb60fe924957771b1e578435f539d46..5a61f381b78c284d58070fdb9c4892738ccd3f0c 100644 (file)
@@ -19,7 +19,6 @@
 
 // ShardDpp implementation
 std::ostream& ECPeeringTestFixture::ShardDpp::gen_prefix(std::ostream& out) const {
-  out << "shard " << shard << ": ";
   if (fixture->shard_peering_states.contains(shard)) {
     PeeringState *ps = fixture->shard_peering_states[shard].get();
     out << *ps;
index c54d3fb603da2e484b6bb4f5ed27e21e14395044..f1eec6c7c7f28eb996b04bd5200e2b4cd84e14be 100644 (file)
@@ -15,7 +15,6 @@
 
 #pragma once
 
-#include <iostream>
 #include <functional>
 #include <deque>
 #include <map>
@@ -27,6 +26,7 @@
 #include "osd/OpRequest.h"
 #include "osd/PeeringState.h"
 #include "os/ObjectStore.h"
+#include "common/dout.h"
 
 /**
  * EventLoop - Unified single-threaded event loop for OSD tests.
@@ -48,7 +48,37 @@ public:
     PEERING_EVENT
   };
   
+  /**
+   * Get the log prefix for the currently executing context.
+   * Returns "osd.X" if an OSD is currently executing, "harness" if not.
+   * This is used by Log::_flush() to replace thread IDs with meaningful names.
+   */
+  static const char* get_log_prefix() {
+    static thread_local char prefix_buf[32];
+    
+    // Read the value once to ensure consistency within this call
+    int osd_id = current_executing_osd;
+    
+    if (osd_id >= 0) {
+      snprintf(prefix_buf, sizeof(prefix_buf), "osd.%d", osd_id);
+      return prefix_buf;
+    }
+    // osd_id is -1 (harness/test code, not in OSD event)
+    return "harness";
+  }
+  
+  /**
+   * Get the OSD number currently executing in the EventLoop.
+   * Returns -1 if no OSD is currently executing or if called outside an EventLoop context.
+   * This is a simple static variable that can be easily accessed from lldb at any time.
+   */
+  static int get_current_executing_osd() {
+    return current_executing_osd;
+  }
+  
 private:
+  // Static storage for the currently executing OSD
+  static int current_executing_osd;
   struct Event {
     EventType type;
     int from_osd;  // -1 for generic events or when not applicable
@@ -60,13 +90,13 @@ private:
   };
   
   std::deque<Event> events;
-  bool verbose = false;
   int events_executed = 0;
   std::map<EventType, int> events_by_type;
   std::set<int> suspended_from_osds;
   std::set<int> suspended_to_osds;
   std::set<std::pair<int, int>> suspended_from_to_osds;
   int current_osd = -1;
+  DoutPrefixProvider *dpp;
   
   // Map from OSD number to its queue of suspended events
   std::map<int, std::deque<Event>> suspended_events;
@@ -87,7 +117,7 @@ private:
   }
   
 public:
-  EventLoop(bool verbose = false) : verbose(verbose) {}
+  EventLoop(DoutPrefixProvider *dpp) : dpp(dpp) {}
   
   void schedule_generic(GenericEvent event) {
     events.emplace_back(EventType::GENERIC, -1, -1, std::move(event));
@@ -96,6 +126,8 @@ public:
   void schedule_osd_message(int from_osd, int to_osd, GenericEvent callback) {
     ceph_assert(from_osd >= 0);
     ceph_assert(to_osd >= 0);
+    ldpp_dout(dpp, 20) << "EventLoop: scheduling OSD_MESSAGE from OSD." << from_osd
+                       << " to OSD." << to_osd << dendl;
     events.emplace_back(EventType::OSD_MESSAGE, from_osd, to_osd, std::move(callback));
   }
   
@@ -107,12 +139,16 @@ public:
   void schedule_peering_message(int from_osd, int to_osd, GenericEvent callback) {
     ceph_assert(from_osd >= 0);
     ceph_assert(to_osd >= 0);
+    ldpp_dout(dpp, 20) << "EventLoop: scheduling PEERING_MESSAGE from OSD." << from_osd
+                       << " to OSD." << to_osd << dendl;
     events.emplace_back(EventType::PEERING_MESSAGE, from_osd, to_osd, std::move(callback));
   }
   
   void schedule_cluster_message(int from_osd, int to_osd, GenericEvent callback) {
     ceph_assert(from_osd >= 0);
     ceph_assert(to_osd >= 0);
+    ldpp_dout(dpp, 20) << "EventLoop: scheduling CLUSTER_MESSAGE from OSD." << from_osd
+                       << " to OSD." << to_osd << dendl;
     events.emplace_back(EventType::CLUSTER_MESSAGE, from_osd, to_osd, std::move(callback));
   }
   
@@ -172,68 +208,32 @@ public:
     
     if (should_suspend) {
       // Move to suspended queue
-      if (verbose) {
-        std::cout << "  [Event " << (events_executed + 1) << "] "
-                  << event_type_name(event.type);
-        if (event.from_osd >= 0 && event.to_osd >= 0) {
-          std::cout << " (OSD." << event.from_osd << " -> OSD." << event.to_osd << ")";
-        } else if (event.to_osd >= 0) {
-          std::cout << " (to OSD." << event.to_osd << ")";
-        } else if (event.from_osd >= 0) {
-          std::cout << " (from OSD." << event.from_osd << ")";
-        }
-        std::cout << " *** SUSPENDED - moving to suspended queue ***" << std::endl;
-      }
       suspended_events[suspend_osd].push_back(std::move(event));
       return true;  // We processed an event (by suspending it)
     }
     
-    // Print banner if switching to a different OSD
+    // Track which OSD we're currently processing
     int active_osd = (event.to_osd >= 0) ? event.to_osd : event.from_osd;
     if (active_osd >= 0 && active_osd != current_osd) {
       current_osd = active_osd;
-      if (verbose) {
-        std::cout << "\n==== Processing events for OSD." << current_osd
-                  << " ====" << std::endl;
-      }
     }
     
-    if (verbose) {
-      std::cout << "  [Event " << (events_executed + 1) << "] "
-                << event_type_name(event.type);
-      if (event.from_osd >= 0 && event.to_osd >= 0) {
-        std::cout << " (OSD." << event.from_osd << " -> OSD." << event.to_osd << ")";
-      } else if (event.to_osd >= 0) {
-        std::cout << " (to OSD." << event.to_osd << ")";
-      } else if (event.from_osd >= 0) {
-        std::cout << " (from OSD." << event.from_osd << ")";
-      }
-      std::cout << " Executing..." << std::endl;
-    }
+    current_executing_osd = active_osd;
     
     // Execute the event
     event.callback();
     events_executed++;
     events_by_type[event.type]++;
+    current_executing_osd = -1;
     
     return true;
   }
   
   int run_many(int count) {
-    if (verbose) {
-      std::cout << "\n=== Running " << count << " events ===" << std::endl;
-    }
-    
     int executed = 0;
     for (int i = 0; i < count && run_one(); i++) {
       executed++;
     }
-    
-    if (verbose) {
-      std::cout << "=== Executed " << executed << " events, "
-                << events.size() << " remaining ===" << std::endl;
-    }
-    
     return executed;
   }
 
@@ -253,14 +253,6 @@ public:
    * Returns -1 if max_events was reached before the queue emptied.
    */
   void run_until_idle(int max_events = 10000) {
-    if (verbose) {
-      std::cout << "\n=== Running until idle";
-      if (max_events > 0) {
-        std::cout << " (max " << max_events << " events)";
-      }
-      std::cout << " ===" << std::endl;
-    }
-
     do {
       ceph_assert(--max_events);
       while (has_events()) {
@@ -274,10 +266,6 @@ public:
     suspended_events.clear();
   }
   
-  void set_verbose(bool v) {
-    verbose = v;
-  }
-  
   // OSD management methods
   /**
    * Suspend events FROM an OSD - events originating from this OSD will be queued
@@ -285,9 +273,6 @@ public:
    */
   void suspend_from_osd(int osd) {
     suspended_from_osds.insert(osd);
-    if (verbose) {
-      std::cout << "*** Events FROM OSD." << osd << " marked as SUSPENDED ***" << std::endl;
-    }
   }
   
   /**
@@ -300,21 +285,11 @@ public:
     // Move all suspended events for this OSD back to the main queue
     auto it = suspended_events.find(osd);
     if (it != suspended_events.end()) {
-      if (verbose) {
-        std::cout << "*** Events FROM OSD." << osd << " marked as UNSUSPENDED - restoring "
-                  << it->second.size() << " suspended events ***" << std::endl;
-      }
-      
       // Append suspended events to the main queue
       for (auto& event : it->second) {
         events.push_back(std::move(event));
       }
-      
       suspended_events.erase(it);
-    } else {
-      if (verbose) {
-        std::cout << "*** Events FROM OSD." << osd << " marked as UNSUSPENDED ***" << std::endl;
-      }
     }
   }
   
@@ -324,9 +299,6 @@ public:
    */
   void suspend_to_osd(int osd) {
     suspended_to_osds.insert(osd);
-    if (verbose) {
-      std::cout << "*** Events TO OSD." << osd << " marked as SUSPENDED ***" << std::endl;
-    }
   }
   
   /**
@@ -339,21 +311,11 @@ public:
     // Move all suspended events for this OSD back to the main queue
     auto it = suspended_events.find(osd);
     if (it != suspended_events.end()) {
-      if (verbose) {
-        std::cout << "*** Events TO OSD." << osd << " marked as UNSUSPENDED - restoring "
-                  << it->second.size() << " suspended events ***" << std::endl;
-      }
-      
       // Append suspended events to the main queue
       for (auto& event : it->second) {
         events.push_back(std::move(event));
       }
-      
       suspended_events.erase(it);
-    } else {
-      if (verbose) {
-        std::cout << "*** Events TO OSD." << osd << " marked as UNSUSPENDED ***" << std::endl;
-      }
     }
   }
   
@@ -363,10 +325,6 @@ public:
    */
   void suspend_from_to_osd(int from_osd, int to_osd) {
     suspended_from_to_osds.insert({from_osd, to_osd});
-    if (verbose) {
-      std::cout << "*** Events FROM OSD." << from_osd << " TO OSD." << to_osd
-                << " marked as SUSPENDED ***" << std::endl;
-    }
   }
   
   /**
@@ -379,23 +337,11 @@ public:
     // Move all suspended events for this OSD pair back to the main queue
     auto it = suspended_events.find(to_osd);
     if (it != suspended_events.end()) {
-      if (verbose) {
-        std::cout << "*** Events FROM OSD." << from_osd << " TO OSD." << to_osd
-                  << " marked as UNSUSPENDED - restoring "
-                  << it->second.size() << " suspended events ***" << std::endl;
-      }
-      
       // Append suspended events to the main queue
       for (auto& event : it->second) {
         events.push_back(std::move(event));
       }
-      
       suspended_events.erase(it);
-    } else {
-      if (verbose) {
-        std::cout << "*** Events FROM OSD." << from_osd << " TO OSD." << to_osd
-                  << " marked as UNSUSPENDED ***" << std::endl;
-      }
     }
   }
   
@@ -437,3 +383,7 @@ public:
   }
 };
 
+// Define the static variable
+// Initialized to -1 (no OSD currently executing)
+inline int EventLoop::current_executing_osd = -1;
+
index 0269f9c3c2653da5ae46f9d11356b3cbba29402f..0e728f3f38c0131687c8ee5e66f281c0240be5ff 100644 (file)
@@ -109,16 +109,7 @@ protected:
   // The epoch comes from osdmap, this tracks the second version number
   uint64_t next_version = 1;
   
-  class TestDpp : public NoDoutPrefix {
-  public:
-    TestDpp(CephContext *cct) : NoDoutPrefix(cct, ceph_subsys_osd) {}
-    
-    std::ostream& gen_prefix(std::ostream& out) const override {
-      out << "PGBackendTest: ";
-      return out;
-    }
-  };
-  std::unique_ptr<TestDpp> dpp;
+  std::unique_ptr<NoDoutPrefix> dpp;
 
 public:
   explicit PGBackendTestFixture(PoolType type = EC) : pool_type(type)
@@ -142,6 +133,7 @@ public:
   }
   
   void SetUp() override {
+    ceph::logging::Log::set_prefix_hook(&EventLoop::get_log_prefix);
     int r = ::mkdir(data_dir.c_str(), 0777);
     if (r < 0) {
       r = -errno;
@@ -158,8 +150,14 @@ public:
     g_conf().set_safe_to_start_threads();
     
     CephContext *cct = g_ceph_context;
-    dpp = std::make_unique<TestDpp>(cct);
-    event_loop = std::make_unique<EventLoop>(false);
+    
+    // Make dout statements flush immediately - we don't care about performance in tests
+    if (cct->_log) {
+      cct->_log->set_max_new(1);
+    }
+    
+    dpp = std::make_unique<NoDoutPrefix>(cct, ceph_subsys_osd);
+    event_loop = std::make_unique<EventLoop>(dpp.get());
     
     if (pool_type == EC) {
       setup_ec_pool();
@@ -208,6 +206,7 @@ public:
     }
 
     cleanup_data_dir();
+    ceph::logging::Log::set_prefix_hook(nullptr);
   }
   
 private: