From: Alex Ainscow Date: Sun, 3 May 2026 16:46:00 +0000 (+0100) Subject: test/osd: Improve test logging with OSD identification X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=c7bbe58ae7a89b6a8db818fe704042c80c6b5682;p=ceph.git test/osd: Improve test logging with OSD identification 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 --- diff --git a/src/log/Log.cc b/src/log/Log.cc index 989438abbfd..4a79f0def28 100644 --- a/src/log/Log.cc +++ b/src/log/Log.cc @@ -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'; diff --git a/src/log/Log.h b/src/log/Log.h index 99b636eb13a..226afbd78ca 100644 --- a/src/log/Log.h +++ b/src/log/Log.h @@ -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; diff --git a/src/test/osd/ECPeeringTestFixture.cc b/src/test/osd/ECPeeringTestFixture.cc index 172aa9a8dfb..5a61f381b78 100644 --- a/src/test/osd/ECPeeringTestFixture.cc +++ b/src/test/osd/ECPeeringTestFixture.cc @@ -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; diff --git a/src/test/osd/EventLoop.h b/src/test/osd/EventLoop.h index c54d3fb603d..f1eec6c7c7f 100644 --- a/src/test/osd/EventLoop.h +++ b/src/test/osd/EventLoop.h @@ -15,7 +15,6 @@ #pragma once -#include #include #include #include @@ -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 events; - bool verbose = false; int events_executed = 0; std::map events_by_type; std::set suspended_from_osds; std::set suspended_to_osds; std::set> suspended_from_to_osds; int current_osd = -1; + DoutPrefixProvider *dpp; // Map from OSD number to its queue of suspended events std::map> 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; + diff --git a/src/test/osd/PGBackendTestFixture.h b/src/test/osd/PGBackendTestFixture.h index 0269f9c3c26..0e728f3f38c 100644 --- a/src/test/osd/PGBackendTestFixture.h +++ b/src/test/osd/PGBackendTestFixture.h @@ -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 dpp; + std::unique_ptr 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(cct); - event_loop = std::make_unique(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(cct, ceph_subsys_osd); + event_loop = std::make_unique(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: