From 3f2ada34398b1c08706b8297b890ba2431d22983 Mon Sep 17 00:00:00 2001 From: Ayaz Salikhov Date: Mon, 15 Sep 2025 14:47:35 +0100 Subject: [PATCH] fix: Keep spdlog loggers valid between tests (#2614) --- benchmarks/util/log/LoggerBenchmark.cpp | 8 +- src/util/Assert.cpp | 2 +- src/util/log/Logger.cpp | 140 +++++++++++++----- src/util/log/Logger.hpp | 105 ++++++++++--- tests/common/util/AsioContextTestFixture.hpp | 4 +- tests/common/util/LoggerBuffer.hpp | 43 ++++++ tests/common/util/LoggerFixtures.cpp | 49 +++--- tests/common/util/LoggerFixtures.hpp | 28 ++-- tests/common/util/MockBackendTestFixture.hpp | 2 +- tests/common/util/MockCountersFixture.hpp | 2 +- .../common/util/MockETLServiceTestFixture.hpp | 10 +- .../util/MockMigrationBackendFixture.hpp | 2 +- tests/common/util/SyncExecutionCtxFixture.hpp | 2 +- .../integration/data/cassandra/BaseTests.cpp | 2 +- .../CassandraMigrationManagerTests.cpp | 2 +- tests/unit/Main.cpp | 3 + tests/unit/app/StopperTests.cpp | 2 +- tests/unit/app/WebHandlersTests.cpp | 2 +- tests/unit/data/LedgerCacheTests.cpp | 4 +- .../data/cassandra/SettingsProviderTests.cpp | 2 +- tests/unit/etl/CorruptionDetectorTests.cpp | 2 +- tests/unit/etl/ETLStateTests.cpp | 2 +- tests/unit/etl/ExtractionDataPipeTests.cpp | 2 +- tests/unit/etl/ExtractorTests.cpp | 2 +- tests/unit/etl/GrpcSourceTests.cpp | 2 +- tests/unit/etl/NFTHelpersTests.cpp | 2 +- tests/unit/etlng/ExtractionTests.cpp | 6 +- tests/unit/etlng/GrpcSourceTests.cpp | 2 +- .../etlng/NetworkValidatedLedgersTests.cpp | 2 +- tests/unit/etlng/RegistryTests.cpp | 2 +- tests/unit/etlng/SchedulingTests.cpp | 2 +- tests/unit/etlng/TaskManagerTests.cpp | 2 +- tests/unit/etlng/ext/CacheTests.cpp | 2 +- .../MigrationManagerFactoryTests.cpp | 2 +- .../cassandra/FullTableScannerTests.cpp | 2 +- tests/unit/rpc/APIVersionTests.cpp | 2 +- tests/unit/rpc/BaseTests.cpp | 2 +- tests/unit/rpc/CountersTests.cpp | 2 +- tests/unit/rpc/WorkQueueTests.cpp | 2 +- tests/unit/util/SignalsHandlerTests.cpp | 2 +- .../util/config/ClioConfigDefinitionTests.cpp | 2 +- .../unit/util/config/ConfigFileJsonTests.cpp | 5 +- tests/unit/util/config/ConfigValueTests.cpp | 4 +- tests/unit/util/log/LogServiceInitTests.cpp | 50 +++---- tests/unit/util/log/LoggerTests.cpp | 18 +-- tests/unit/web/AdminVerificationTests.cpp | 4 +- tests/unit/web/ServerTests.cpp | 2 +- tests/unit/web/SubscriptionContextTests.cpp | 2 +- tests/unit/web/dosguard/DOSGuardTests.cpp | 2 +- .../web/dosguard/WhitelistHandlerTests.cpp | 2 +- tests/unit/web/impl/ErrorHandlingTests.cpp | 2 +- tests/unit/web/ng/ServerTests.cpp | 4 +- tests/unit/web/ng/impl/ErrorHandlingTests.cpp | 2 +- 53 files changed, 353 insertions(+), 204 deletions(-) create mode 100644 tests/common/util/LoggerBuffer.hpp diff --git a/benchmarks/util/log/LoggerBenchmark.cpp b/benchmarks/util/log/LoggerBenchmark.cpp index cc36c0da..0b7467e3 100644 --- a/benchmarks/util/log/LoggerBenchmark.cpp +++ b/benchmarks/util/log/LoggerBenchmark.cpp @@ -42,7 +42,7 @@ using namespace util; static constexpr auto kLOG_FORMAT = "%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v"; struct BenchmarkLoggingInitializer { - static std::shared_ptr + [[nodiscard]] static std::shared_ptr createFileSink(LogService::FileLoggingParams const& params) { return LogService::createFileSink(params, kLOG_FORMAT); @@ -72,8 +72,6 @@ uniqueLogDir() static void benchmarkConcurrentFileLogging(benchmark::State& state) { - spdlog::drop_all(); - auto const numThreads = static_cast(state.range(0)); auto const messagesPerThread = static_cast(state.range(1)); @@ -84,7 +82,9 @@ benchmarkConcurrentFileLogging(benchmark::State& state) state.PauseTiming(); std::filesystem::create_directories(logDir); - spdlog::init_thread_pool(8192, 1); + static constexpr size_t kQUEUE_SIZE = 8192; + static constexpr size_t kTHREAD_COUNT = 1; + spdlog::init_thread_pool(kQUEUE_SIZE, kTHREAD_COUNT); auto fileSink = BenchmarkLoggingInitializer::createFileSink({ .logDir = logDir, diff --git a/src/util/Assert.cpp b/src/util/Assert.cpp index 1acb6988..87165d60 100644 --- a/src/util/Assert.cpp +++ b/src/util/Assert.cpp @@ -54,7 +54,7 @@ OnAssert::resetAction() void OnAssert::defaultAction(std::string_view message) { - if (LogService::enabled()) { + if (LogServiceState::initialized()) { LOG(LogService::fatal()) << message; } else { std::cerr << message; diff --git a/src/util/log/Logger.cpp b/src/util/log/Logger.cpp index 5c0da1df..576cf3bf 100644 --- a/src/util/log/Logger.cpp +++ b/src/util/log/Logger.cpp @@ -41,12 +41,12 @@ #include #include -#include #include #include #include #include #include +#include #include #include #include @@ -56,7 +56,10 @@ namespace util { -LogService::Data LogService::data{}; +bool LogServiceState::isAsync_{true}; +Severity LogServiceState::defaultSeverity_{Severity::NFO}; +std::vector LogServiceState::sinks_{}; +bool LogServiceState::initialized_{false}; namespace { @@ -238,23 +241,71 @@ getMinSeverity(config::ClioConfigDefinition const& config, Severity defaultSever return minSeverity; } -std::shared_ptr -LogService::registerLogger(std::string const& channel, Severity severity) +void +LogServiceState::init(bool isAsync, Severity defaultSeverity, std::vector const& sinks) { - std::shared_ptr logger; - if (data.isAsync) { - logger = std::make_shared( - channel, - data.allSinks.begin(), - data.allSinks.end(), - spdlog::thread_pool(), - spdlog::async_overflow_policy::block - ); - } else { - logger = std::make_shared(channel, data.allSinks.begin(), data.allSinks.end()); + if (initialized_) { + throw std::logic_error("LogServiceState is already initialized"); } - logger->set_level(toSpdlogLevel(severity)); + isAsync_ = isAsync; + defaultSeverity_ = defaultSeverity; + sinks_ = sinks; + initialized_ = true; + + spdlog::apply_all([](std::shared_ptr logger) { + logger->set_level(toSpdlogLevel(defaultSeverity_)); + }); + + if (isAsync) { + static constexpr size_t kQUEUE_SIZE = 8192; + static constexpr size_t kTHREAD_COUNT = 1; + spdlog::init_thread_pool(kQUEUE_SIZE, kTHREAD_COUNT); + } +} + +bool +LogServiceState::initialized() +{ + return initialized_; +} + +void +LogServiceState::reset() +{ + if (not initialized()) { + throw std::logic_error("LogService is not initialized"); + } + isAsync_ = true; + defaultSeverity_ = Severity::NFO; + sinks_.clear(); + initialized_ = false; +} + +std::shared_ptr +LogServiceState::registerLogger(std::string const& channel, std::optional severity) +{ + if (not initialized_) { + throw std::logic_error("LogService is not initialized"); + } + + std::shared_ptr existingLogger = spdlog::get(channel); + if (existingLogger != nullptr) { + if (severity.has_value()) + existingLogger->set_level(toSpdlogLevel(*severity)); + return existingLogger; + } + + std::shared_ptr logger; + if (isAsync_) { + logger = std::make_shared( + channel, sinks_.begin(), sinks_.end(), spdlog::thread_pool(), spdlog::async_overflow_policy::block + ); + } else { + logger = std::make_shared(channel, sinks_.begin(), sinks_.end()); + } + + logger->set_level(toSpdlogLevel(severity.value_or(defaultSeverity_))); logger->flush_on(spdlog::level::err); spdlog::register_logger(logger); @@ -262,22 +313,12 @@ LogService::registerLogger(std::string const& channel, Severity severity) return logger; } -std::expected -LogService::init(config::ClioConfigDefinition const& config) +std::expected, std::string> +LogService::getSinks(config::ClioConfigDefinition const& config) { - // Drop existing loggers - spdlog::drop_all(); - - data.isAsync = config.get("log.is_async"); - data.defaultSeverity = getSeverityLevel(config.get("log.level")); - std::string const format = config.get("log.format"); - if (data.isAsync) { - spdlog::init_thread_pool(8192, 1); - } - - data.allSinks = createConsoleSinks(config.get("log.enable_console"), format); + std::vector allSinks = createConsoleSinks(config.get("log.enable_console"), format); if (auto const logDir = config.maybeValue("log.directory"); logDir.has_value()) { std::filesystem::path const dirPath{logDir.value()}; @@ -294,11 +335,27 @@ LogService::init(config::ClioConfigDefinition const& config) .rotationSizeMB = config.get("log.rotation_size"), .dirMaxFiles = config.get("log.directory_max_files"), }; - data.allSinks.push_back(createFileSink(params, format)); + allSinks.push_back(createFileSink(params, format)); + } + return allSinks; +} + +std::expected +LogService::init(config::ClioConfigDefinition const& config) +{ + auto const sinksMaybe = getSinks(config); + if (!sinksMaybe.has_value()) { + return std::unexpected{sinksMaybe.error()}; } + LogServiceState::init( + config.get("log.is_async"), + getSeverityLevel(config.get("log.level")), + std::move(sinksMaybe).value() + ); + // get min severity per channel, can be overridden using the `log.channels` array - auto const maybeMinSeverity = getMinSeverity(config, data.defaultSeverity); + auto const maybeMinSeverity = getMinSeverity(config, defaultSeverity_); if (!maybeMinSeverity) { return std::unexpected{maybeMinSeverity.error()}; } @@ -307,20 +364,23 @@ LogService::init(config::ClioConfigDefinition const& config) // Create loggers for each channel for (auto const& channel : Logger::kCHANNELS) { auto const it = minSeverity.find(channel); - auto const severity = (it != minSeverity.end()) ? it->second : data.defaultSeverity; + auto const severity = (it != minSeverity.end()) ? it->second : defaultSeverity_; registerLogger(channel, severity); } spdlog::set_default_logger(spdlog::get("General")); - LOG(LogService::info()) << "Default log level = " << toString(data.defaultSeverity); + LOG(LogService::info()) << "Default log level = " << toString(defaultSeverity_); return {}; } void LogService::shutdown() { - spdlog::shutdown(); + if (initialized_ && isAsync_) { + // We run in async mode in production, so we need to make sure all logs are flushed before shutting down + spdlog::shutdown(); + } } Logger::Pump @@ -359,17 +419,15 @@ LogService::fatal(SourceLocationType const& loc) return Logger(spdlog::default_logger()).fatal(loc); } -bool -LogService::enabled() +void +LogServiceState::replaceSinks(std::vector> const& sinks) { - return spdlog::get_level() != spdlog::level::off; + sinks_ = sinks; + spdlog::apply_all([](std::shared_ptr logger) { logger->sinks() = sinks_; }); } -Logger::Logger(std::string channel) : logger_(spdlog::get(channel)) +Logger::Logger(std::string channel) : logger_(LogServiceState::registerLogger(channel)) { - if (!logger_) { - logger_ = LogService::registerLogger(channel); - } } Logger::Pump::Pump(std::shared_ptr logger, Severity sev, SourceLocationType const& loc) diff --git a/src/util/log/Logger.hpp b/src/util/log/Logger.hpp index 49209ff0..7ba17b71 100644 --- a/src/util/log/Logger.hpp +++ b/src/util/log/Logger.hpp @@ -26,6 +26,7 @@ #include #include #include +#include #include #include #include @@ -43,9 +44,15 @@ class sink; // NOLINT(readability-identifier-naming) } // namespace spdlog struct BenchmarkLoggingInitializer; +class LoggerFixture; +struct LogServiceInitTests; namespace util { +namespace impl { +class OnAssert; +} // namespace impl + namespace config { class ClioConfigDefinition; } // namespace config @@ -228,27 +235,78 @@ private: Logger(std::shared_ptr logger); }; +/** + * @brief Base state management class for the logging service. + * + * This class manages the global state and core functionality for the logging system, + * including initialization, sink management, and logger registration. + */ +class LogServiceState { +protected: + friend struct ::LogServiceInitTests; + friend class ::LoggerFixture; + friend class Logger; + friend class ::util::impl::OnAssert; + + /** + * @brief Initialize the logging core with specified parameters. + * + * @param isAsync Whether logging should be asynchronous + * @param defaultSeverity The default severity level for new loggers + * @param sinks Vector of spdlog sinks to use for output + */ + static void + init(bool isAsync, Severity defaultSeverity, std::vector> const& sinks); + + /** + * @brief Whether the LogService is initialized or not + * + * @return true if the LogService is initialized + */ + [[nodiscard]] static bool + initialized(); + + /** + * @brief Reset the logging service to uninitialized state. + */ + static void + reset(); + + /** + * @brief Replace the current sinks with a new set of sinks. + * + * @param sinks Vector of new spdlog sinks to replace the current ones + */ + static void + replaceSinks(std::vector> const& sinks); + + /** + * @brief Register a new logger for the specified channel. + * + * Creates and registers a new spdlog logger instance for the given channel + * with the specified or default severity level. + * + * @param channel The name of the logging channel + * @param severity Optional severity level override; uses default if not specified + * @return Shared pointer to the registered spdlog logger + */ + static std::shared_ptr + registerLogger(std::string const& channel, std::optional severity = std::nullopt); + +protected: + static bool isAsync_; // NOLINT(readability-identifier-naming) + static Severity defaultSeverity_; // NOLINT(readability-identifier-naming) + static std::vector> sinks_; // NOLINT(readability-identifier-naming) + static bool initialized_; // NOLINT(readability-identifier-naming) +}; + /** * @brief A global logging service. * * Used to initialize and setup the logging core as well as a globally available * entrypoint for logging into the `General` channel as well as raising alerts. */ -class LogService { - struct Data { - bool isAsync; - Severity defaultSeverity; - std::vector> allSinks; - }; - - friend class Logger; - -private: - static Data data; - - static std::shared_ptr - registerLogger(std::string const& channel, Severity severity = data.defaultSeverity); - +class LogService : public LogServiceState { public: LogService() = delete; @@ -321,15 +379,16 @@ public: [[nodiscard]] static Logger::Pump fatal(SourceLocationType const& loc = CURRENT_SRC_LOCATION); - /** - * @brief Whether the LogService is enabled or not - * - * @return true if the LogService is enabled, false otherwise - */ - [[nodiscard]] static bool - enabled(); - private: + /** + * @brief Parses the sinks from a @ref config::ClioConfigDefinition + * + * @param config The configuration to parse sinks from + * @return A vector of sinks on success, error message on failure + */ + [[nodiscard]] static std::expected>, std::string> + getSinks(config::ClioConfigDefinition const& config); + struct FileLoggingParams { std::string logDir; diff --git a/tests/common/util/AsioContextTestFixture.hpp b/tests/common/util/AsioContextTestFixture.hpp index e98670a9..2c1fb536 100644 --- a/tests/common/util/AsioContextTestFixture.hpp +++ b/tests/common/util/AsioContextTestFixture.hpp @@ -40,7 +40,7 @@ * * This is meant to be used as a base for other fixtures. */ -struct AsyncAsioContextTest : virtual public NoLoggerFixture { +struct AsyncAsioContextTest : virtual public ::testing::Test { AsyncAsioContextTest() { work_.emplace(boost::asio::make_work_guard(ctx_)); // make sure ctx does not stop on its own @@ -79,7 +79,7 @@ private: * Use `run_for(duration)` etc. directly on `ctx`. * This is meant to be used as a base for other fixtures. */ -struct SyncAsioContextTest : virtual public NoLoggerFixture { +struct SyncAsioContextTest : virtual public ::testing::Test { template void runCoroutine(F&& f, bool allowMockLeak = false) diff --git a/tests/common/util/LoggerBuffer.hpp b/tests/common/util/LoggerBuffer.hpp new file mode 100644 index 00000000..5e7f3e15 --- /dev/null +++ b/tests/common/util/LoggerBuffer.hpp @@ -0,0 +1,43 @@ +//------------------------------------------------------------------------------ +/* + This file is part of clio: https://github.com/XRPLF/clio + Copyright (c) 2025, the clio developers. + + Permission to use, copy, modify, and distribute this software for any + purpose with or without fee is hereby granted, provided that the above + copyright notice and this permission notice appear in all copies. + + THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. +*/ +//============================================================================== + +#pragma once +#include "util/StringBuffer.hpp" + +#include +#include + +class LoggerBuffer { +public: + std::string + getStrAndReset() + { + return buffer_.getStrAndReset(); + } + + std::ostream& + getStream() + { + return stream_; + } + +private: + StringBuffer buffer_; + std::ostream stream_ = std::ostream{&buffer_}; +}; diff --git a/tests/common/util/LoggerFixtures.cpp b/tests/common/util/LoggerFixtures.cpp index d0649be6..23a8710e 100644 --- a/tests/common/util/LoggerFixtures.cpp +++ b/tests/common/util/LoggerFixtures.cpp @@ -22,6 +22,7 @@ #include "util/log/Logger.hpp" #include +#include #include #include #include @@ -29,32 +30,40 @@ #include #include -LoggerFixture::LoggerFixture() +void +LoggerFixture::init() { - // Clear any existing loggers - spdlog::drop_all(); + util::LogServiceState::init(false, util::Severity::FTL, {}); - // Create ostream sink for testing - auto ostreamSink = std::make_shared(stream_); - ostreamSink->set_formatter(std::make_unique("%^%3!l:%n%$ - %v")); - - // Create loggers for each channel - std::ranges::for_each(util::Logger::kCHANNELS, [&ostreamSink](char const* channel) { - auto logger = std::make_shared(channel, ostreamSink); - logger->set_level(spdlog::level::trace); - spdlog::register_logger(logger); + std::ranges::for_each(util::Logger::kCHANNELS, [](char const* channel) { + util::LogService::registerLogger(channel); }); - spdlog::get("General")->set_level(spdlog::level::debug); - - auto traceLogger = std::make_shared("Trace", ostreamSink); - traceLogger->set_level(spdlog::level::trace); - spdlog::register_logger(traceLogger); - spdlog::set_default_logger(spdlog::get("General")); } -NoLoggerFixture::NoLoggerFixture() +void +LoggerFixture::resetTestingLoggers() { - spdlog::set_level(spdlog::level::off); + auto ostreamSink = std::make_shared(buffer_.getStream()); + ostreamSink->set_formatter(std::make_unique("%^%3!l:%n%$ - %v")); + ostreamSink->set_level(spdlog::level::trace); + util::LogServiceState::replaceSinks({ostreamSink}); + + spdlog::apply_all([](std::shared_ptr logger) { logger->set_level(spdlog::level::trace); }); + spdlog::get("General")->set_level(spdlog::level::debug); +} + +LoggerFixture::LoggerFixture() +{ + util::LogServiceState::reset(); + util::LogServiceState::init(false, util::Severity::TRC, {}); + + resetTestingLoggers(); +} + +LoggerFixture::~LoggerFixture() +{ + util::LogServiceState::replaceSinks({}); + spdlog::apply_all([](std::shared_ptr logger) { logger->set_level(spdlog::level::critical); }); } diff --git a/tests/common/util/LoggerFixtures.hpp b/tests/common/util/LoggerFixtures.hpp index e221ad16..1d4633fa 100644 --- a/tests/common/util/LoggerFixtures.hpp +++ b/tests/common/util/LoggerFixtures.hpp @@ -19,37 +19,39 @@ #pragma once -#include "util/StringBuffer.hpp" +#include "util/LoggerBuffer.hpp" #include -#include #include /** * @brief A fixture for testing LogService and Logger. */ class LoggerFixture : virtual public ::testing::Test { - StringBuffer buffer_; - std::ostream stream_ = std::ostream{&buffer_}; +protected: + LoggerBuffer buffer_; public: - // Simulates the `util::LogService::init(config)` call LoggerFixture(); + ~LoggerFixture() override; + + /** + * @brief Sets up spdlog loggers for each channel. Should be called once before using any loggers. + * Simulates the `util::LogService::init(config)` call + */ + static void + init(); protected: + [[nodiscard]] std::string getLoggerString() { return buffer_.getStrAndReset(); } -}; -/** - * @brief Fixture with util::Logger support but completely disabled logging. - * - * This is meant to be used as a base for other fixtures. - */ -struct NoLoggerFixture : virtual LoggerFixture { - NoLoggerFixture(); +private: + void + resetTestingLoggers(); }; diff --git a/tests/common/util/MockBackendTestFixture.hpp b/tests/common/util/MockBackendTestFixture.hpp index 4e47e5c3..06c84e37 100644 --- a/tests/common/util/MockBackendTestFixture.hpp +++ b/tests/common/util/MockBackendTestFixture.hpp @@ -29,7 +29,7 @@ #include template