From 9420c506ca0b1def7ec5e7e24b2ae6af7ab46d90 Mon Sep 17 00:00:00 2001 From: Ayaz Salikhov Date: Mon, 11 Aug 2025 18:04:04 +0100 Subject: [PATCH] feat: Use spdlog logger (#2372) --- CMakeLists.txt | 1 + benchmarks/CMakeLists.txt | 2 +- benchmarks/util/log/LoggerBenchmark.cpp | 51 ++- cmake/deps/spdlog.cmake | 5 + conan.lock | 1 + conanfile.py | 3 +- docs/config-description.md | 28 +- docs/examples/config/example-config.json | 9 +- docs/logging.md | 38 ++- src/app/Stopper.hpp | 2 + src/main/Main.cpp | 2 + src/util/CMakeLists.txt | 3 +- src/util/ScopeGuard.hpp | 57 ++++ src/util/TerminationHandler.cpp | 3 + src/util/config/ConfigDefinition.cpp | 13 +- src/util/config/ConfigDescription.hpp | 12 +- src/util/log/Logger.cpp | 309 ++++++++++-------- src/util/log/Logger.hpp | 159 ++++----- tests/common/CMakeLists.txt | 2 +- tests/common/util/LoggerFixtures.cpp | 48 ++- tests/common/util/LoggerFixtures.hpp | 39 +-- tests/common/util/StringBuffer.hpp | 37 +++ tests/unit/CMakeLists.txt | 4 +- tests/unit/LogServiceInitTests.cpp | 232 +++++++++++++ tests/unit/LoggerTests.cpp | 191 +---------- tests/unit/etl/AmendmentBlockHandlerTests.cpp | 2 +- .../unit/etlng/AmendmentBlockHandlerTests.cpp | 2 +- tests/unit/rpc/RPCHelpersTests.cpp | 6 +- tests/unit/util/ScopeGuardTests.cpp | 32 ++ 29 files changed, 745 insertions(+), 548 deletions(-) create mode 100644 cmake/deps/spdlog.cmake create mode 100644 src/util/ScopeGuard.hpp create mode 100644 tests/common/util/StringBuffer.hpp create mode 100644 tests/unit/LogServiceInitTests.cpp create mode 100644 tests/unit/util/ScopeGuardTests.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 410aba7f..2633a373 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -58,6 +58,7 @@ include(deps/Threads) include(deps/libfmt) include(deps/cassandra) include(deps/libbacktrace) +include(deps/spdlog) add_subdirectory(src) add_subdirectory(tests) diff --git a/benchmarks/CMakeLists.txt b/benchmarks/CMakeLists.txt index a2fc070b..ec2d91eb 100644 --- a/benchmarks/CMakeLists.txt +++ b/benchmarks/CMakeLists.txt @@ -14,5 +14,5 @@ target_sources( include(deps/gbench) target_include_directories(clio_benchmark PRIVATE .) -target_link_libraries(clio_benchmark PUBLIC clio_util benchmark::benchmark_main) +target_link_libraries(clio_benchmark PUBLIC clio_util benchmark::benchmark_main spdlog::spdlog) set_target_properties(clio_benchmark PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) diff --git a/benchmarks/util/log/LoggerBenchmark.cpp b/benchmarks/util/log/LoggerBenchmark.cpp index 5953910e..b492f042 100644 --- a/benchmarks/util/log/LoggerBenchmark.cpp +++ b/benchmarks/util/log/LoggerBenchmark.cpp @@ -22,26 +22,36 @@ #include "util/prometheus/Prometheus.hpp" #include -#include -#include +#include +#include +#include +#include #include #include #include #include +#include #include #include +#include #include using namespace util; -struct BenchmarkLoggingInitializer { - static constexpr auto kLOG_FORMAT = "%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%"; +static constexpr auto kLOG_FORMAT = "%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v"; - static void - initFileLogging(LogService::FileLoggingParams const& params) +struct BenchmarkLoggingInitializer { + static std::shared_ptr + createFileSink(LogService::FileLoggingParams const& params) { - LogService::initFileLogging(params, kLOG_FORMAT); + return LogService::createFileSink(params); + } + + static Logger + getLogger(std::shared_ptr logger) + { + return Logger(std::move(logger)); } }; @@ -53,7 +63,7 @@ uniqueLogDir() auto const epochTime = std::chrono::high_resolution_clock::now().time_since_epoch(); auto const tmpDir = std::filesystem::temp_directory_path(); std::string const dirName = - "logs_" + std::to_string(std::chrono::duration_cast(epochTime).count()); + fmt::format("logs_{}", std::chrono::duration_cast(epochTime).count()); return tmpDir / "clio_benchmark" / dirName; } @@ -62,7 +72,7 @@ uniqueLogDir() static void benchmarkConcurrentFileLogging(benchmark::State& state) { - boost::log::add_common_attributes(); + spdlog::drop_all(); auto const numThreads = static_cast(state.range(0)); auto const messagesPerThread = static_cast(state.range(1)); @@ -74,12 +84,12 @@ benchmarkConcurrentFileLogging(benchmark::State& state) state.PauseTiming(); std::filesystem::create_directories(logDir); + spdlog::init_thread_pool(8192, 1); - BenchmarkLoggingInitializer::initFileLogging({ + auto fileSink = BenchmarkLoggingInitializer::createFileSink({ .logDir = logDir, .rotationSizeMB = 5, - .dirMaxSizeMB = 125, - .rotationHours = 24, + .dirMaxFiles = 25, }); std::vector threads; @@ -92,10 +102,16 @@ benchmarkConcurrentFileLogging(benchmark::State& state) }); for (size_t threadNum = 0; threadNum < numThreads; ++threadNum) { - threads.emplace_back([threadNum, messagesPerThread, &barrier]() { - barrier.arrive_and_wait(); + threads.emplace_back([threadNum, messagesPerThread, fileSink, &barrier]() { + std::string const channel = fmt::format("Thread_{}", threadNum); + auto logger = std::make_shared( + channel, fileSink, spdlog::thread_pool(), spdlog::async_overflow_policy::block + ); + logger->set_pattern(kLOG_FORMAT); + spdlog::register_logger(logger); + Logger const threadLogger = BenchmarkLoggingInitializer::getLogger(std::move(logger)); - Logger const threadLogger("Thread_" + std::to_string(threadNum)); + barrier.arrive_and_wait(); for (size_t messageNum = 0; messageNum < messagesPerThread; ++messageNum) { LOG(threadLogger.info()) << "Test log message #" << messageNum; @@ -106,10 +122,9 @@ benchmarkConcurrentFileLogging(benchmark::State& state) for (auto& thread : threads) { thread.join(); } - boost::log::core::get()->flush(); + spdlog::shutdown(); auto const end = std::chrono::high_resolution_clock::now(); - state.SetIterationTime(std::chrono::duration_cast>(end - start).count()); std::filesystem::remove_all(logDir); @@ -129,7 +144,7 @@ BENCHMARK(benchmarkConcurrentFileLogging) // Number of threads {1, 2, 4, 8}, // Messages per thread - {10'000, 100'000, 500'000}, + {10'000, 100'000, 500'000, 1'000'000, 10'000'000}, }) ->UseManualTime() ->Unit(benchmark::kMillisecond); diff --git a/cmake/deps/spdlog.cmake b/cmake/deps/spdlog.cmake new file mode 100644 index 00000000..957a6c34 --- /dev/null +++ b/cmake/deps/spdlog.cmake @@ -0,0 +1,5 @@ +find_package(spdlog REQUIRED) + +if (NOT TARGET spdlog::spdlog) + message(FATAL_ERROR "spdlog::spdlog target not found") +endif () diff --git a/conan.lock b/conan.lock index 1cd5a207..903eadfe 100644 --- a/conan.lock +++ b/conan.lock @@ -5,6 +5,7 @@ "xxhash/0.8.2#7856c968c985b2981b707ee8f2413b2b%1754325010.01", "xrpl/2.5.0@clio/boost-odr#f68e48da1490c0a583052e4f068ada55%1754325014.392", "sqlite3/3.47.0#7a0904fd061f5f8a2366c294f9387830%1754325009.708", + "spdlog/1.15.3#3ca0e9e6b83af4d0151e26541d140c86%1754401846.61", "soci/4.0.3#a9f8d773cd33e356b5879a4b0564f287%1754412158.144", "re2/20230301#dfd6e2bf050eb90ddd8729cfb4c844a4%1754412148.014", "rapidjson/cci.20220822#1b9d8c2256876a154172dc5cfbe447c6%1754325007.656", diff --git a/conanfile.py b/conanfile.py index dd6a4e7a..9248c88a 100644 --- a/conanfile.py +++ b/conanfile.py @@ -33,7 +33,8 @@ class ClioConan(ConanFile): 'openssl/1.1.1v', 'xrpl/2.5.0@clio/boost-odr', 'zlib/1.3.1', - 'libbacktrace/cci.20210118' + 'libbacktrace/cci.20210118', + 'spdlog/1.15.3', ] default_options = { diff --git a/docs/config-description.md b/docs/config-description.md index e2936c1c..a071aa3f 100644 --- a/docs/config-description.md +++ b/docs/config-description.md @@ -439,13 +439,21 @@ This document provides a list of all available Clio configuration properties in - **Constraints**: The value must be one of the following: `trace`, `debug`, `info`, `warning`, `error`, `fatal`. - **Description**: The general logging level of Clio. This level is applied to all log channels that do not have an explicitly defined logging level. -### log_format +### spdlog_format - **Required**: True - **Type**: string -- **Default value**: `%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%` +- **Default value**: `%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v` - **Constraints**: None -- **Description**: The format string for log messages. The format is described here: . +- **Description**: The format string for log messages using spdlog format patterns. Documentation can be found at: . + +### spdlog_async + +- **Required**: True +- **Type**: boolean +- **Default value**: `True` +- **Constraints**: None +- **Description**: Whether spdlog is asynchronous or not. ### log_to_console @@ -471,21 +479,13 @@ This document provides a list of all available Clio configuration properties in - **Constraints**: The minimum value is `1`. The maximum value is `4294967295`. - **Description**: The log rotation size in megabytes. When the log file reaches this particular size, a new log file starts. -### log_directory_max_size +### log_directory_max_files - **Required**: True - **Type**: int -- **Default value**: `51200` +- **Default value**: `25` - **Constraints**: The minimum value is `1`. The maximum value is `4294967295`. -- **Description**: The maximum size of the log directory in megabytes. - -### log_rotation_hour_interval - -- **Required**: True -- **Type**: int -- **Default value**: `12` -- **Constraints**: The minimum value is `1`. The maximum value is `4294967295`. -- **Description**: Represents the interval (in hours) for log rotation. If the current log file reaches this value in logging, a new log file starts. +- **Description**: The maximum number of log files in the directory. ### log_tag_style diff --git a/docs/examples/config/example-config.json b/docs/examples/config/example-config.json index 6129a458..94c51bc4 100644 --- a/docs/examples/config/example-config.json +++ b/docs/examples/config/example-config.json @@ -122,14 +122,15 @@ "compress_reply": true }, "log_level": "info", - // Log format (this is the default format) - "log_format": "%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%", + // Log format using spdlog format patterns (this is the default format) + "spdlog_format": "%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v", + // Whether spdlog is asynchronous or not. + "spdlog_async": true, "log_to_console": true, // Clio logs to file in the specified directory only if "log_directory" is set // "log_directory": "./clio_log", "log_rotation_size": 2048, - "log_directory_max_size": 51200, - "log_rotation_hour_interval": 12, + "log_directory_max_files": 25, "log_tag_style": "uint", "extractor_threads": 8, "read_only": false, diff --git a/docs/logging.md b/docs/logging.md index 8e5de6fa..7f95ba7d 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -6,18 +6,29 @@ Clio provides several logging options, which all are configurable via the config The minimum level of severity at which the log message will be outputted by default. Severity options are `trace`, `debug`, `info`, `warning`, `error`, `fatal`. Defaults to `info`. -## `log_format` +## `spdlog_format` -The format of log lines produced by Clio. Defaults to `"%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%"`. +The format of log lines produced by Clio using spdlog format patterns. Defaults to `"%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v"`. Each of the variables expands like so: -- `TimeStamp`: The full date and time of the log entry -- `SourceLocation`: A partial path to the c++ file and the line number in said file (`source/file/path:linenumber`) -- `ThreadID`: The ID of the thread the log entry is written from -- `Channel`: The channel that this log entry was sent to -- `Severity`: The severity (aka log level) the entry was sent at -- `Message`: The actual log message +- `%Y-%m-%d %H:%M:%S.%f`: The full date and time of the log entry with microsecond precision +- `%^`: Start color range +- `%3!l`: The severity (aka log level) the entry was sent at stripped to 3 characters +- `%n`: The logger name (channel) that this log entry was sent to +- `%$`: End color range +- `%v`: The actual log message + +Some additional variables that might be useful: + +- `%@`: A partial path to the C++ file and the line number in the said file (`src/file/path:linenumber`) +- `%t`: The ID of the thread the log entry is written from + +For more information about spdlog format patterns, see: + +## `spdlog_async` + +Whether spdlog is asynchronous or not. ## `log_channels` @@ -56,16 +67,9 @@ If the option is not specified, the logs are not written to a file. The max size of the log file in **megabytes** before it will rotate into a smaller file. Defaults to 2GB. -## `log_directory_max_size` +## `log_directory_max_files` -The max size of the log directory in **megabytes** before old log files will be deleted to free up space. Defaults to 50GB. - -## `log_rotation_hour_interval` - -The time interval in **hours** after the last log rotation to automatically rotate the current log file. Defaults to 12 hours. - -> [!NOTE] -> Log rotation based on time occurs in conjunction with size-based log rotation. For example, if a size-based log rotation occurs, the timer for the time-based rotation will reset. +The max number of log files in the directory before old log files will be deleted to free up space. Defaults to 25. ## `log_tag_style` diff --git a/src/app/Stopper.hpp b/src/app/Stopper.hpp index daba1164..593cfb09 100644 --- a/src/app/Stopper.hpp +++ b/src/app/Stopper.hpp @@ -108,6 +108,8 @@ public: ioc.stop(); LOG(util::LogService::info()) << "io_context stopped"; + + util::LogService::shutdown(); }; } }; diff --git a/src/main/Main.cpp b/src/main/Main.cpp index 667d50db..8cec627d 100644 --- a/src/main/Main.cpp +++ b/src/main/Main.cpp @@ -22,6 +22,7 @@ #include "app/VerifyConfig.hpp" #include "migration/MigrationApplication.hpp" #include "rpc/common/impl/HandlerProvider.hpp" +#include "util/ScopeGuard.hpp" #include "util/TerminationHandler.hpp" #include "util/config/ConfigDefinition.hpp" #include "util/log/Logger.hpp" @@ -37,6 +38,7 @@ int main(int argc, char const* argv[]) try { util::setTerminationHandler(); + util::ScopeGuard loggerShutdownGuard{[]() { util::LogService::shutdown(); }}; auto const action = app::CliArgs::parse(argc, argv); return action.apply( diff --git a/src/util/CMakeLists.txt b/src/util/CMakeLists.txt index 11394320..e7b96253 100644 --- a/src/util/CMakeLists.txt +++ b/src/util/CMakeLists.txt @@ -50,8 +50,6 @@ target_link_libraries( clio_util PUBLIC Boost::headers Boost::iostreams - Boost::log - Boost::log_setup fmt::fmt openssl::openssl xrpl::libxrpl @@ -59,6 +57,7 @@ target_link_libraries( clio_options clio_rpc_center clio_build_version + PRIVATE spdlog::spdlog ) # FIXME: needed on gcc-12, clang-16 and AppleClang for now (known boost 1.82 issue for some compilers) diff --git a/src/util/ScopeGuard.hpp b/src/util/ScopeGuard.hpp new file mode 100644 index 00000000..0c00d1ee --- /dev/null +++ b/src/util/ScopeGuard.hpp @@ -0,0 +1,57 @@ +//------------------------------------------------------------------------------ +/* + 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 + +namespace util { + +/** + * @brief Run a function when the scope is exited + */ +template +class ScopeGuard { +public: + ScopeGuard(ScopeGuard const&) = delete; + ScopeGuard(ScopeGuard&&) = delete; + ScopeGuard& + operator=(ScopeGuard const&) = delete; + ScopeGuard& + operator=(ScopeGuard&&) = delete; + + /** + * @brief Create ScopeGuard object. + * + * @param func The function to run when the scope is exited. + */ + ScopeGuard(Func func) : func_(std::move(func)) + { + } + + ~ScopeGuard() + { + func_(); + } + +private: + Func func_; +}; + +} // namespace util diff --git a/src/util/TerminationHandler.cpp b/src/util/TerminationHandler.cpp index 9343841f..8a924834 100644 --- a/src/util/TerminationHandler.cpp +++ b/src/util/TerminationHandler.cpp @@ -44,6 +44,9 @@ terminationHandler() #else LOG(LogService::fatal()) << "Exit on terminate. Stacktrace disabled."; #endif // CLIO_WITHOUT_STACKTRACE + + // We're calling std::abort later, so spdlog won't be shutdown automatically + util::LogService::shutdown(); std::abort(); } diff --git a/src/util/config/ConfigDefinition.cpp b/src/util/config/ConfigDefinition.cpp index 519fbbe2..c134647e 100644 --- a/src/util/config/ConfigDefinition.cpp +++ b/src/util/config/ConfigDefinition.cpp @@ -358,10 +358,9 @@ getClioConfig() {"log_level", ConfigValue{ConfigType::String}.defaultValue("info").withConstraint(gValidateLogLevelName)}, - {"log_format", - ConfigValue{ConfigType::String}.defaultValue( - R"(%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%)" - )}, + {"spdlog_format", ConfigValue{ConfigType::String}.defaultValue(R"(%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v)")}, + + {"spdlog_async", ConfigValue{ConfigType::Boolean}.defaultValue(true)}, {"log_to_console", ConfigValue{ConfigType::Boolean}.defaultValue(false)}, @@ -369,11 +368,7 @@ getClioConfig() {"log_rotation_size", ConfigValue{ConfigType::Integer}.defaultValue(2048).withConstraint(gValidateUint32)}, - {"log_directory_max_size", - ConfigValue{ConfigType::Integer}.defaultValue(50 * 1024).withConstraint(gValidateUint32)}, - - {"log_rotation_hour_interval", - ConfigValue{ConfigType::Integer}.defaultValue(12).withConstraint(gValidateUint32)}, + {"log_directory_max_files", ConfigValue{ConfigType::Integer}.defaultValue(25).withConstraint(gValidateUint32)}, {"log_tag_style", ConfigValue{ConfigType::String}.defaultValue("none").withConstraint(gValidateLogTag)}, diff --git a/src/util/config/ConfigDescription.hpp b/src/util/config/ConfigDescription.hpp index 3e7a36e0..6ee16856 100644 --- a/src/util/config/ConfigDescription.hpp +++ b/src/util/config/ConfigDescription.hpp @@ -263,18 +263,16 @@ private: KV{.key = "log_level", .value = "The general logging level of Clio. This level is applied to all log channels that do not have an " "explicitly defined logging level."}, - KV{.key = "log_format", - .value = "The format string for log messages. The format is described here: " - "."}, + KV{.key = "spdlog_format", + .value = "The format string for log messages using spdlog format patterns. Documentation can be found at: " + "."}, + KV{.key = "spdlog_async", .value = "Whether spdlog is asynchronous or not."}, KV{.key = "log_to_console", .value = "Enables or disables logging to the console."}, KV{.key = "log_directory", .value = "The directory path for the log files."}, KV{.key = "log_rotation_size", .value = "The log rotation size in megabytes. When the log file reaches this particular size, a new log " "file starts."}, - KV{.key = "log_directory_max_size", .value = "The maximum size of the log directory in megabytes."}, - KV{.key = "log_rotation_hour_interval", - .value = "Represents the interval (in hours) for log rotation. If the current log file reaches this value " - "in logging, a new log file starts."}, + KV{.key = "log_directory_max_files", .value = "The maximum number of log files in the directory."}, KV{.key = "log_tag_style", .value = "Log tags are unique identifiers for log messages. `uint`/`int` starts logging from 0 and increments, " diff --git a/src/util/log/Logger.cpp b/src/util/log/Logger.cpp index 6aaaef82..cb6e5fa3 100644 --- a/src/util/log/Logger.cpp +++ b/src/util/log/Logger.cpp @@ -25,83 +25,62 @@ #include "util/config/ArrayView.hpp" #include "util/config/ConfigDefinition.hpp" #include "util/config/ObjectView.hpp" -#include "util/prometheus/Counter.hpp" -#include "util/prometheus/Label.hpp" -#include "util/prometheus/Prometheus.hpp" #include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include #include +#include +#include +#include +#include +#include +#include +#include +#include #include #include #include #include -#include #include -#include -#include -#include +#include #include -#include #include #include #include #include #include +#include namespace util { +LogService::Data LogService::data{}; + namespace { -class LoggerExceptionHandler { - std::reference_wrapper exceptionCounter_ = - PrometheusService::counterInt("logger_exceptions_total_number", util::prometheus::Labels{}); - -public: - using result_type = void; - - LoggerExceptionHandler() - { - ASSERT(PrometheusService::isInitialised(), "Prometheus should be initialised before Logger"); - } - - void - operator()(std::exception const& e) const - { - std::cerr << fmt::format("Exception in logger: {}\n", e.what()); - ++exceptionCounter_.get(); - } -}; - -} // namespace - -Logger LogService::generalLog = Logger{"General"}; -boost::log::filter LogService::filter{}; - -std::ostream& -operator<<(std::ostream& stream, Severity sev) +spdlog::level::level_enum +toSpdlogLevel(Severity sev) { - static constexpr std::array kLABELS = { + switch (sev) { + case Severity::TRC: + return spdlog::level::trace; + case Severity::DBG: + return spdlog::level::debug; + case Severity::NFO: + return spdlog::level::info; + case Severity::WRN: + return spdlog::level::warn; + case Severity::ERR: + return spdlog::level::err; + case Severity::FTL: + return spdlog::level::critical; + } + return spdlog::level::info; +} + +std::string_view +toString(Severity sev) +{ + static constexpr std::array kLABELS = { "TRC", "DBG", "NFO", @@ -110,9 +89,11 @@ operator<<(std::ostream& stream, Severity sev) "FTL", }; - return stream << kLABELS.at(static_cast(sev)); + return kLABELS.at(static_cast(sev)); } +} // namespace + /** * @brief converts the loglevel to string to a corresponding Severity enum value. * @@ -144,60 +125,47 @@ getSeverityLevel(std::string_view logLevel) * @brief Initializes console logging. * * @param logToConsole A boolean indicating whether to log to console. - * @param format The log format string. + * @return Vector of sinks for console logging. */ -static void -initConsoleLogging(bool logToConsole, std::string const& format) +static std::vector +createConsoleSinks(bool logToConsole) { - namespace keywords = boost::log::keywords; + std::vector sinks; if (logToConsole) { - boost::log::add_console_log( - std::cout, keywords::format = format, keywords::filter = LogSeverity < Severity::FTL - ); + auto consoleSink = std::make_shared(); + consoleSink->set_level(spdlog::level::trace); + sinks.push_back(std::move(consoleSink)); } - // Always print fatal logs to cerr - boost::log::add_console_log(std::cerr, keywords::format = format, keywords::filter = LogSeverity >= Severity::FTL); + // Always add stderr sink for fatal logs + auto stderrSink = std::make_shared(); + stderrSink->set_level(spdlog::level::critical); + sinks.push_back(std::move(stderrSink)); + + return sinks; } /** * @brief Initializes file logging. * * @param config The configuration object containing log settings. - * @param format The log format string. * @param dirPath The directory path where log files will be stored. + * @return File sink for logging. */ -void -LogService::initFileLogging(FileLoggingParams const& params, std::string const& format) +spdlog::sink_ptr +LogService::createFileSink(FileLoggingParams const& params) { - namespace keywords = boost::log::keywords; - namespace sinks = boost::log::sinks; - - // the below are taken from user in MB, but boost::log::add_file_log needs it to be in bytes + std::filesystem::path const dirPath(params.logDir); + // the below are taken from user in MB, but spdlog needs it to be in bytes auto const rotationSize = mbToBytes(params.rotationSizeMB); - auto const dirSize = mbToBytes(params.dirMaxSizeMB); - auto const dirPath = std::filesystem::path{params.logDir}; + auto fileSink = std::make_shared( + (dirPath / "clio.log").string(), rotationSize, params.dirMaxFiles + ); + fileSink->set_level(spdlog::level::trace); - auto fileSink = boost::log::add_file_log( - keywords::file_name = dirPath / "clio.log", - keywords::target_file_name = dirPath / "clio_%Y-%m-%d_%H-%M-%S.log", - keywords::auto_flush = true, - keywords::format = format, - keywords::open_mode = std::ios_base::app, - keywords::rotation_size = rotationSize, - keywords::time_based_rotation = - sinks::file::rotation_at_time_interval(boost::posix_time::hours(params.rotationHours)) - ); - fileSink->locked_backend()->set_file_collector( - sinks::file::make_collector(keywords::target = dirPath, keywords::max_size = dirSize) - ); - fileSink->locked_backend()->scan_for_files(); - - boost::log::core::get()->set_exception_handler( - boost::log::make_exception_handler(LoggerExceptionHandler()) - ); + return fileSink; } /** @@ -229,41 +197,45 @@ getMinSeverity(config::ClioConfigDefinition const& config, Severity defaultSever return minSeverity; } -/** - * @brief Creates a log filter based on the minimum severity levels for each channel. - * - * @param defaultSeverity The default severity level to use if not overridden. - * @param minSeverity A map of channel names to their minimum severity levels. - * @return A boost::log::filter that filters log records based on the severity level. - */ -static boost::log::filter -createLogFilter(Severity defaultSeverity, std::unordered_map const& minSeverity) +std::shared_ptr +LogService::registerLogger(std::string const& channel, Severity severity) { - auto logFilter = [minSeverity = minSeverity, - defaultSeverity](boost::log::attribute_value_set const& attributes) -> bool { - auto const channel = attributes[LogChannel]; - auto const severity = attributes[LogSeverity]; - if (!channel || !severity) - return false; - if (auto const it = minSeverity.find(channel.get()); it != minSeverity.end()) - return severity.get() >= it->second; - return severity.get() >= defaultSeverity; - }; + 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()); + } - return boost::log::filter{std::move(logFilter)}; + logger->set_level(toSpdlogLevel(severity)); + logger->flush_on(spdlog::level::err); + + spdlog::register_logger(logger); + + return logger; } std::expected LogService::init(config::ClioConfigDefinition const& config) { - boost::log::add_common_attributes(); - boost::log::register_simple_formatter_factory("Severity"); - std::string const format = config.get("log_format"); + // Drop existing loggers + spdlog::drop_all(); - initConsoleLogging(config.get("log_to_console"), format); + data.isAsync = config.get("spdlog_async"); - auto const logDir = config.maybeValue("log_directory"); - if (logDir) { + if (data.isAsync) { + spdlog::init_thread_pool(8192, 1); + } + + data.allSinks = createConsoleSinks(config.get("log_to_console")); + + if (auto const logDir = config.maybeValue("log_directory"); logDir.has_value()) { std::filesystem::path const dirPath{logDir.value()}; if (not std::filesystem::exists(dirPath)) { if (std::error_code error; not std::filesystem::create_directories(dirPath, error)) { @@ -272,13 +244,13 @@ LogService::init(config::ClioConfigDefinition const& config) }; } } + FileLoggingParams const params{ .logDir = logDir.value(), .rotationSizeMB = config.get("log_rotation_size"), - .dirMaxSizeMB = config.get("log_directory_max_size"), - .rotationHours = config.get("log_rotation_hour_interval") + .dirMaxFiles = config.get("log_directory_max_files"), }; - initFileLogging(params, format); + data.allSinks.push_back(createFileSink(params)); } // get default severity, can be overridden per channel using the `log_channels` array @@ -289,17 +261,92 @@ LogService::init(config::ClioConfigDefinition const& config) } auto const minSeverity = std::move(maybeMinSeverity).value(); - auto logFilter = createLogFilter(defaultSeverity, minSeverity); - boost::log::core::get()->set_filter(logFilter); + // 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 : defaultSeverity; + registerLogger(channel, severity); + } - LOG(LogService::info()) << "Default log level = " << defaultSeverity; + spdlog::set_default_logger(spdlog::get("General")); + + std::string const format = config.get("spdlog_format"); + spdlog::set_pattern(format); + + LOG(LogService::info()) << "Default log level = " << toString(defaultSeverity); return {}; } +void +LogService::shutdown() +{ + LOG(LogService::info()) << "Shutting down logger"; + spdlog::shutdown(); +} + +Logger::Pump +LogService::trace(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).trace(loc); +} + +Logger::Pump +LogService::debug(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).debug(loc); +} + +Logger::Pump +LogService::info(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).info(loc); +} + +Logger::Pump +LogService::warn(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).warn(loc); +} + +Logger::Pump +LogService::error(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).error(loc); +} + +Logger::Pump +LogService::fatal(SourceLocationType const& loc) +{ + return Logger(spdlog::default_logger()).fatal(loc); +} + bool LogService::enabled() { - return boost::log::core::get()->get_logging_enabled(); + return spdlog::get_level() != spdlog::level::off; +} + +Logger::Logger(std::string channel) : logger_(spdlog::get(channel)) +{ + if (!logger_) { + logger_ = LogService::registerLogger(channel); + } +} + +Logger::Pump::Pump(std::shared_ptr logger, Severity sev, SourceLocationType const& loc) + : logger_(std::move(logger)) + , severity_(sev) + , sourceLocation_(loc) + , enabled_(logger_ != nullptr && logger_->should_log(toSpdlogLevel(sev))) +{ +} + +Logger::Pump::~Pump() +{ + if (enabled_) { + spdlog::source_loc sourceLocation{prettyPath(sourceLocation_).cbegin(), sourceLocation_.line(), nullptr}; + logger_->log(sourceLocation, toSpdlogLevel(severity_), std::move(stream_).str()); + } } Logger::Pump @@ -333,17 +380,21 @@ Logger::fatal(SourceLocationType const& loc) const return {logger_, Severity::FTL, loc}; } -std::string +Logger::Logger(std::shared_ptr logger) : logger_(std::move(logger)) +{ +} + +std::string_view Logger::Pump::prettyPath(SourceLocationType const& loc, size_t maxDepth) { - auto const filePath = std::string{loc.file_name()}; + std::string_view filePath{loc.file_name()}; auto idx = filePath.size(); while (maxDepth-- > 0) { idx = filePath.rfind('/', idx - 1); if (idx == std::string::npos || idx == 0) break; } - return filePath.substr(idx == std::string::npos ? 0 : idx + 1) + ':' + std::to_string(loc.line()); + return filePath.substr(idx == std::string::npos ? 0 : idx + 1); } } // namespace util diff --git a/src/util/log/Logger.hpp b/src/util/log/Logger.hpp index ce10cf3d..ee9b6b32 100644 --- a/src/util/log/Logger.hpp +++ b/src/util/log/Logger.hpp @@ -21,35 +21,27 @@ #include "util/SourceLocation.hpp" -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include - #include #include +#include #include -#include -#include +#include +#include #include +#include +#include + +// We forward declare spdlog::logger and spdlog::sinks::sink +// to avoid including the spdlog headers in this header file. +namespace spdlog { + +class logger; + +namespace sinks { +class sink; +} // namespace sinks + +} // namespace spdlog struct BenchmarkLoggingInitializer; @@ -85,23 +77,6 @@ enum class Severity { FTL, }; -/** @cond */ -// NOLINTBEGIN(readability-identifier-naming) -BOOST_LOG_ATTRIBUTE_KEYWORD(LogSeverity, "Severity", Severity); -BOOST_LOG_ATTRIBUTE_KEYWORD(LogChannel, "Channel", std::string); -// NOLINTEND(readability-identifier-naming) -/** @endcond */ - -/** - * @brief Custom labels for @ref Severity in log output. - * - * @param stream std::ostream The output stream - * @param sev Severity The severity to output to the ostream - * @return The same ostream we were given - */ -std::ostream& -operator<<(std::ostream& stream, Severity sev); - /** * @brief A simple thread-safe logger for the channel specified * in the constructor. @@ -111,31 +86,25 @@ operator<<(std::ostream& stream, Severity sev); * severity levels for each channel. */ class Logger final { - using LoggerType = boost::log::sources::severity_channel_logger_mt; - mutable LoggerType logger_; + std::shared_ptr logger_; friend class LogService; // to expose the Pump interface + friend struct ::BenchmarkLoggingInitializer; /** * @brief Helper that pumps data into a log record via `operator<<`. */ class Pump final { - using PumpOptType = std::optional>; - - boost::log::record rec_; - PumpOptType pump_ = std::nullopt; + std::shared_ptr logger_; + Severity const severity_; + SourceLocationType const sourceLocation_; + std::ostringstream stream_; + bool const enabled_; public: - ~Pump() = default; + ~Pump(); - Pump(LoggerType& logger, Severity sev, SourceLocationType const& loc) - : rec_{logger.open_record(boost::log::keywords::severity = sev)} - { - if (rec_) { - pump_.emplace(boost::log::aux::make_record_pump(logger, rec_)); - pump_->stream() << boost::log::add_value("SourceLocation", prettyPath(loc)); - } - } + Pump(std::shared_ptr logger, Severity sev, SourceLocationType const& loc); Pump(Pump&&) = delete; Pump(Pump const&) = delete; @@ -145,7 +114,7 @@ class Logger final { operator=(Pump&&) = delete; /** - * @brief Perfectly forwards any incoming data into the underlying boost::log pump if the pump is available. + * @brief Perfectly forwards any incoming data into the underlying stream if data should be logged. * * @tparam T Type of data to pump * @param data The data to pump @@ -155,8 +124,8 @@ class Logger final { [[maybe_unused]] Pump& operator<<(T&& data) { - if (pump_) - pump_->stream() << std::forward(data); + if (enabled_) + stream_ << std::forward(data); return *this; } @@ -165,11 +134,11 @@ class Logger final { */ operator bool() const { - return pump_.has_value(); + return enabled_; } private: - [[nodiscard]] static std::string + [[nodiscard]] static std::string_view prettyPath(SourceLocationType const& loc, size_t maxDepth = 3); }; @@ -194,9 +163,7 @@ public: * * @param channel The channel this logger will report into. */ - Logger(std::string channel) : logger_{boost::log::keywords::channel = channel} - { - } + Logger(std::string channel); Logger(Logger const&) = default; ~Logger() = default; @@ -261,6 +228,9 @@ public: */ [[nodiscard]] Pump fatal(SourceLocationType const& loc = CURRENT_SRC_LOCATION) const; + +private: + Logger(std::shared_ptr logger); }; /** @@ -270,8 +240,19 @@ public: * entrypoint for logging into the `General` channel as well as raising alerts. */ class LogService { - static Logger generalLog; /*< Global logger for General channel */ - static boost::log::filter filter; + struct Data { + bool isAsync; + Severity severity; + std::vector> allSinks; + }; + + friend class Logger; + +private: + static Data data; + + static std::shared_ptr + registerLogger(std::string const& channel, Severity severity = data.severity); public: LogService() = delete; @@ -285,6 +266,12 @@ public: [[nodiscard]] static std::expected init(config::ClioConfigDefinition const& config); + /** + * @brief Shutdown spdlog to guarantee output is not lost + */ + static void + shutdown(); + /** * @brief Globally accessible General logger at Severity::TRC severity * @@ -292,10 +279,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - trace(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.trace(loc); - } + trace(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Globally accessible General logger at Severity::DBG severity @@ -304,10 +288,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - debug(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.debug(loc); - } + debug(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Globally accessible General logger at Severity::NFO severity @@ -316,10 +297,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - info(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.info(loc); - } + info(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Globally accessible General logger at Severity::WRN severity @@ -328,10 +306,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - warn(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.warn(loc); - } + warn(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Globally accessible General logger at Severity::ERR severity @@ -340,10 +315,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - error(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.error(loc); - } + error(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Globally accessible General logger at Severity::FTL severity @@ -352,10 +324,7 @@ public: * @return The pump to use for logging */ [[nodiscard]] static Logger::Pump - fatal(SourceLocationType const& loc = CURRENT_SRC_LOCATION) - { - return generalLog.fatal(loc); - } + fatal(SourceLocationType const& loc = CURRENT_SRC_LOCATION); /** * @brief Whether the LogService is enabled or not @@ -370,14 +339,14 @@ private: std::string logDir; uint32_t rotationSizeMB; - uint32_t dirMaxSizeMB; - uint32_t rotationHours; + uint32_t dirMaxFiles; }; friend struct ::BenchmarkLoggingInitializer; - static void - initFileLogging(FileLoggingParams const& params, std::string const& format); + [[nodiscard]] + static std::shared_ptr + createFileSink(FileLoggingParams const& params); }; }; // namespace util diff --git a/tests/common/CMakeLists.txt b/tests/common/CMakeLists.txt index c3ab27ca..255c6ecf 100644 --- a/tests/common/CMakeLists.txt +++ b/tests/common/CMakeLists.txt @@ -18,4 +18,4 @@ target_sources( include(deps/gtest) target_include_directories(clio_testing_common PUBLIC .) -target_link_libraries(clio_testing_common PUBLIC clio_app gtest::gtest) +target_link_libraries(clio_testing_common PUBLIC clio_app gtest::gtest PRIVATE spdlog::spdlog) diff --git a/tests/common/util/LoggerFixtures.cpp b/tests/common/util/LoggerFixtures.cpp index 60cfc58b..e4ecea53 100644 --- a/tests/common/util/LoggerFixtures.cpp +++ b/tests/common/util/LoggerFixtures.cpp @@ -21,44 +21,40 @@ #include "util/log/Logger.hpp" -#include -#include -#include -#include -#include -#include +#include +#include +#include #include -#include +#include LoggerFixture::LoggerFixture() { - static std::once_flag kONCE; - std::call_once(kONCE, [] { - boost::log::add_common_attributes(); - boost::log::register_simple_formatter_factory("Severity"); + // Clear any existing loggers + spdlog::drop_all(); + + // Create ostream sink for testing + auto ostreamSink = std::make_shared(stream_); + + // 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); }); - namespace keywords = boost::log::keywords; - namespace expr = boost::log::expressions; - auto core = boost::log::core::get(); + spdlog::get("General")->set_level(spdlog::level::debug); - core->remove_all_sinks(); - boost::log::add_console_log(stream_, keywords::format = "%Channel%:%Severity% %Message%"); - auto minSeverity = expr::channel_severity_filter(util::LogChannel, util::LogSeverity); + auto traceLogger = std::make_shared("Trace", ostreamSink); + traceLogger->set_level(spdlog::level::trace); + spdlog::register_logger(traceLogger); - std::ranges::for_each(util::Logger::kCHANNELS, [&minSeverity](char const* channel) { - minSeverity[channel] = util::Severity::TRC; - }); + spdlog::set_default_logger(spdlog::get("General")); - minSeverity["General"] = util::Severity::DBG; - minSeverity["Trace"] = util::Severity::TRC; - - core->set_filter(minSeverity); - core->set_logging_enabled(true); + spdlog::set_pattern("%^%3!l:%n%$ - %v"); } NoLoggerFixture::NoLoggerFixture() { - boost::log::core::get()->set_logging_enabled(false); + spdlog::set_level(spdlog::level::off); } diff --git a/tests/common/util/LoggerFixtures.hpp b/tests/common/util/LoggerFixtures.hpp index a092e749..e221ad16 100644 --- a/tests/common/util/LoggerFixtures.hpp +++ b/tests/common/util/LoggerFixtures.hpp @@ -19,56 +19,25 @@ #pragma once -#include "util/log/Logger.hpp" +#include "util/StringBuffer.hpp" #include -#include -#include #include -#include #include /** - * @brief Fixture with util::Logger support. + * @brief A fixture for testing LogService and Logger. */ class LoggerFixture : virtual public ::testing::Test { - /** - * @brief A simple string buffer that can be used to mock std::cout for - * console logging. - */ - class FakeBuffer final : public std::stringbuf { - public: - std::string - getStrAndReset() - { - auto value = str(); - str(""); - return value; - } - }; - - FakeBuffer buffer_; + StringBuffer buffer_; std::ostream stream_ = std::ostream{&buffer_}; public: - // Simulates the `util::Logger::init(config)` call + // Simulates the `util::LogService::init(config)` call LoggerFixture(); protected: - void - checkEqual(std::string expected) - { - auto value = buffer_.getStrAndReset(); - ASSERT_EQ(value, expected + '\n') << "Got: " << value; - } - - void - checkEmpty() - { - ASSERT_TRUE(buffer_.getStrAndReset().empty()); - } - std::string getLoggerString() { diff --git a/tests/common/util/StringBuffer.hpp b/tests/common/util/StringBuffer.hpp new file mode 100644 index 00000000..ad20b3a4 --- /dev/null +++ b/tests/common/util/StringBuffer.hpp @@ -0,0 +1,37 @@ +//------------------------------------------------------------------------------ +/* + 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 +#include + +/** + * @brief A simple string buffer that can be used to mock std::cout for console logging. + */ +class StringBuffer final : public std::stringbuf { +public: + std::string + getStrAndReset() + { + auto value = str(); + str(""); + return value; + } +}; diff --git a/tests/unit/CMakeLists.txt b/tests/unit/CMakeLists.txt index e2a82a08..c6c0d342 100644 --- a/tests/unit/CMakeLists.txt +++ b/tests/unit/CMakeLists.txt @@ -69,6 +69,7 @@ target_sources( feed/TrackableSignalTests.cpp feed/TransactionFeedTests.cpp JsonUtilTests.cpp + LogServiceInitTests.cpp LoggerTests.cpp Main.cpp Playground.cpp @@ -173,6 +174,7 @@ target_sources( util/RepeatTests.cpp util/ResponseExpirationCacheTests.cpp util/RetryTests.cpp + util/ScopeGuardTests.cpp util/SignalsHandlerTests.cpp util/SpawnTests.cpp util/StopHelperTests.cpp @@ -216,7 +218,7 @@ gtest_discover_tests(clio_tests DISCOVERY_TIMEOUT 90) target_compile_options(clio_options INTERFACE -gdwarf-4) target_include_directories(clio_tests PRIVATE .) -target_link_libraries(clio_tests PUBLIC clio_testing_common) +target_link_libraries(clio_tests PUBLIC clio_testing_common PRIVATE spdlog::spdlog) set_target_properties(clio_tests PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) # Generate `coverage_report` target if coverage is enabled diff --git a/tests/unit/LogServiceInitTests.cpp b/tests/unit/LogServiceInitTests.cpp new file mode 100644 index 00000000..05f8e1ed --- /dev/null +++ b/tests/unit/LogServiceInitTests.cpp @@ -0,0 +1,232 @@ +//------------------------------------------------------------------------------ +/* + This file is part of clio: https://github.com/XRPLF/clio + Copyright (c) 2022, 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. +*/ +//============================================================================== + +#include "util/StringBuffer.hpp" +#include "util/config/Array.hpp" +#include "util/config/ConfigConstraints.hpp" +#include "util/config/ConfigDefinition.hpp" +#include "util/config/ConfigFileJson.hpp" +#include "util/config/ConfigValue.hpp" +#include "util/config/Types.hpp" +#include "util/log/Logger.hpp" + +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +using namespace util; + +using util::config::Array; +using util::config::ConfigFileJson; +using util::config::ConfigType; +using util::config::ConfigValue; + +struct LogServiceInitTests : virtual public ::testing::Test { +protected: + util::config::ClioConfigDefinition config_{ + {"log_channels.[].channel", Array{ConfigValue{ConfigType::String}}}, + {"log_channels.[].log_level", Array{ConfigValue{ConfigType::String}}}, + + {"log_level", ConfigValue{ConfigType::String}.defaultValue("info")}, + + {"spdlog_format", ConfigValue{ConfigType::String}.defaultValue(R"(%Y-%m-%d %H:%M:%S.%f %^%3!l:%n%$ - %v)")}, + {"spdlog_async", ConfigValue{ConfigType::Boolean}.defaultValue(false)}, + + {"log_to_console", ConfigValue{ConfigType::Boolean}.defaultValue(false)}, + + {"log_directory", ConfigValue{ConfigType::String}.optional()}, + + {"log_rotation_size", + ConfigValue{ConfigType::Integer}.defaultValue(2048).withConstraint(config::gValidateUint32)}, + + {"log_directory_max_files", + ConfigValue{ConfigType::Integer}.defaultValue(25).withConstraint(config::gValidateUint32)}, + + {"log_tag_style", ConfigValue{ConfigType::String}.defaultValue("none")}, + }; + + std::string + getLoggerString() + { + return buffer_.getStrAndReset(); + } + + void + replaceSinks() + { + auto ostreamSink = std::make_shared(stream_); + + for (auto const& channel : Logger::kCHANNELS) { + auto logger = spdlog::get(channel); + ASSERT_TRUE(logger != nullptr); + // It is expected that only stderrSink is present + ASSERT_EQ(logger->sinks().size(), 1); + logger->sinks().clear(); + logger->sinks().push_back(ostreamSink); + } + + spdlog::set_pattern("%^%3!l:%n%$ - %v"); + } + +private: + StringBuffer buffer_; + std::ostream stream_ = std::ostream{&buffer_}; +}; + +TEST_F(LogServiceInitTests, DefaultLogLevel) +{ + auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::object{{"log_level", "warn"}}}); + ASSERT_FALSE(parsingErrors.has_value()); + std::string const logString = "some log"; + + EXPECT_TRUE(LogService::init(config_)); + replaceSinks(); + + for (auto const& channel : Logger::kCHANNELS) { + Logger const log{channel}; + log.trace() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.debug() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.info() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.warn() << logString; + ASSERT_EQ(fmt::format("war:{} - {}\n", channel, logString), getLoggerString()); + + log.error() << logString; + ASSERT_EQ(fmt::format("err:{} - {}\n", channel, logString), getLoggerString()); + } +} + +TEST_F(LogServiceInitTests, ChannelLogLevel) +{ + std::string const configStr = R"JSON( + { + "log_level": "error", + "log_channels": [ + { + "channel": "Backend", + "log_level": "warning" + } + ] + } + )JSON"; + + auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::parse(configStr).as_object()}); + ASSERT_FALSE(parsingErrors.has_value()); + std::string const logString = "some log"; + + EXPECT_TRUE(LogService::init(config_)); + replaceSinks(); + + for (auto const& channel : Logger::kCHANNELS) { + Logger const log{channel}; + log.trace() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.debug() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.info() << logString; + ASSERT_TRUE(getLoggerString().empty()); + + log.warn() << logString; + if (std::string_view{channel} == "Backend") { + ASSERT_EQ(fmt::format("war:{} - {}\n", channel, logString), getLoggerString()); + } else { + ASSERT_TRUE(getLoggerString().empty()); + } + + log.error() << logString; + ASSERT_EQ(fmt::format("err:{} - {}\n", channel, logString), getLoggerString()); + } +} + +TEST_F(LogServiceInitTests, InitReturnsErrorIfCouldNotCreateLogDirectory) +{ + // "/proc" directory is read only on any unix OS + auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::object{{"log_directory", "/proc/logs"}}}); + ASSERT_FALSE(parsingErrors.has_value()); + + auto const result = LogService::init(config_); + EXPECT_FALSE(result); + EXPECT_THAT(result.error(), testing::HasSubstr("Couldn't create logs directory")); +} + +TEST_F(LogServiceInitTests, InitReturnsErrorIfProvidedInvalidChannel) +{ + auto const jsonStr = R"JSON( + { + "log_channels": [ + { + "channel": "SomeChannel", + "log_level": "warn" + } + ] + })JSON"; + + auto const json = boost::json::parse(jsonStr).as_object(); + auto const parsingErrors = config_.parse(ConfigFileJson{json}); + ASSERT_FALSE(parsingErrors.has_value()); + + auto const result = LogService::init(config_); + EXPECT_FALSE(result); + EXPECT_EQ(result.error(), "Can't override settings for log channel SomeChannel: invalid channel"); +} + +TEST_F(LogServiceInitTests, LogSizeAndHourRotationCannotBeZero) +{ + std::vector const keys{"log_directory_max_files", "log_rotation_size"}; + + auto const jsonStr = fmt::format( + R"JSON( + {{ + "{}": 0, + "{}": 0 + }} + )JSON", + keys[0], + keys[1] + ); + + auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::parse(jsonStr).as_object()}); + ASSERT_EQ(parsingErrors->size(), 2); + for (std::size_t i = 0; i < parsingErrors->size(); ++i) { + EXPECT_EQ( + (*parsingErrors)[i].error, + fmt::format("{} Number must be between 1 and {}", keys[i], std::numeric_limits::max()) + ); + } +} diff --git a/tests/unit/LoggerTests.cpp b/tests/unit/LoggerTests.cpp index 59237648..a5f79929 100644 --- a/tests/unit/LoggerTests.cpp +++ b/tests/unit/LoggerTests.cpp @@ -18,27 +18,14 @@ //============================================================================== #include "util/LoggerFixtures.hpp" -#include "util/config/Array.hpp" -#include "util/config/ConfigConstraints.hpp" -#include "util/config/ConfigDefinition.hpp" -#include "util/config/ConfigFileJson.hpp" -#include "util/config/ConfigValue.hpp" -#include "util/config/Types.hpp" #include "util/log/Logger.hpp" -#include -#include -#include #include #include #include #include -#include -#include #include -#include -#include using namespace util; // Used as a fixture for tests with enabled logging @@ -51,189 +38,27 @@ TEST_F(LoggerTest, Basic) { Logger const log{"General"}; log.info() << "Info line logged"; - checkEqual("General:NFO Info line logged"); + ASSERT_EQ(getLoggerString(), "inf:General - Info line logged\n"); LogService::debug() << "Debug line with numbers " << 12345; - checkEqual("General:DBG Debug line with numbers 12345"); + ASSERT_EQ(getLoggerString(), "deb:General - Debug line with numbers 12345\n"); LogService::warn() << "Warning is logged"; - checkEqual("General:WRN Warning is logged"); + ASSERT_EQ(getLoggerString(), "war:General - Warning is logged\n"); } TEST_F(LoggerTest, Filtering) { Logger const log{"General"}; log.trace() << "Should not be logged"; - checkEmpty(); + ASSERT_TRUE(getLoggerString().empty()); log.warn() << "Warning is logged"; - checkEqual("General:WRN Warning is logged"); + ASSERT_EQ(getLoggerString(), "war:General - Warning is logged\n"); Logger const tlog{"Trace"}; tlog.trace() << "Trace line logged for 'Trace' component"; - checkEqual("Trace:TRC Trace line logged for 'Trace' component"); -} - -using util::config::Array; -using util::config::ConfigFileJson; -using util::config::ConfigType; -using util::config::ConfigValue; - -struct LoggerInitTest : LoggerTest { -protected: - util::config::ClioConfigDefinition config_{ - {"log_channels.[].channel", Array{ConfigValue{ConfigType::String}}}, - {"log_channels.[].log_level", Array{ConfigValue{ConfigType::String}}}, - - {"log_level", ConfigValue{ConfigType::String}.defaultValue("info")}, - - {"log_format", - ConfigValue{ConfigType::String}.defaultValue( - R"(%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%)" - )}, - - {"log_to_console", ConfigValue{ConfigType::Boolean}.defaultValue(false)}, - - {"log_directory", ConfigValue{ConfigType::String}.optional()}, - - {"log_rotation_size", - ConfigValue{ConfigType::Integer}.defaultValue(2048).withConstraint(config::gValidateUint32)}, - - {"log_directory_max_size", - ConfigValue{ConfigType::Integer}.defaultValue(50 * 1024).withConstraint(config::gValidateUint32)}, - - {"log_rotation_hour_interval", - ConfigValue{ConfigType::Integer}.defaultValue(12).withConstraint(config::gValidateUint32)}, - - {"log_tag_style", ConfigValue{ConfigType::String}.defaultValue("none")}, - }; -}; - -TEST_F(LoggerInitTest, DefaultLogLevel) -{ - auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::object{{"log_level", "warn"}}}); - ASSERT_FALSE(parsingErrors.has_value()); - std::string const logString = "some log"; - - EXPECT_TRUE(LogService::init(config_)); - for (auto const& channel : Logger::kCHANNELS) { - Logger const log{channel}; - log.trace() << logString; - checkEmpty(); - - log.debug() << logString; - checkEmpty(); - - log.info() << logString; - checkEmpty(); - - log.warn() << logString; - checkEqual(fmt::format("{}:WRN {}", channel, logString)); - - log.error() << logString; - checkEqual(fmt::format("{}:ERR {}", channel, logString)); - } -} - -TEST_F(LoggerInitTest, ChannelLogLevel) -{ - std::string const configStr = R"JSON( - { - "log_level": "error", - "log_channels": [ - { - "channel": "Backend", - "log_level": "warning" - } - ] - } - )JSON"; - - auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::parse(configStr).as_object()}); - ASSERT_FALSE(parsingErrors.has_value()); - std::string const logString = "some log"; - - EXPECT_TRUE(LogService::init(config_)); - for (auto const& channel : Logger::kCHANNELS) { - Logger const log{channel}; - log.trace() << logString; - checkEmpty(); - - log.debug() << logString; - checkEmpty(); - - log.info() << logString; - checkEmpty(); - - log.warn() << logString; - if (std::string_view{channel} == "Backend") { - checkEqual(fmt::format("{}:WRN {}", channel, logString)); - } else { - checkEmpty(); - } - - log.error() << "some log"; - checkEqual(fmt::format("{}:ERR {}", channel, logString)); - } -} - -TEST_F(LoggerInitTest, InitReturnsErrorIfCouldNotCreateLogDirectory) -{ - // "/proc" directory is read only on any unix OS - auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::object{{"log_directory", "/proc/logs"}}}); - ASSERT_FALSE(parsingErrors.has_value()); - - auto const result = LogService::init(config_); - EXPECT_FALSE(result); - EXPECT_THAT(result.error(), testing::HasSubstr("Couldn't create logs directory")); -} - -TEST_F(LoggerInitTest, InitReturnsErrorIfProvidedInvalidChannel) -{ - auto const jsonStr = R"JSON( - { - "log_channels": [ - { - "channel": "SomeChannel", - "log_level": "warn" - } - ] - })JSON"; - - auto const json = boost::json::parse(jsonStr).as_object(); - auto const parsingErrors = config_.parse(ConfigFileJson{json}); - ASSERT_FALSE(parsingErrors.has_value()); - - auto const result = LogService::init(config_); - EXPECT_FALSE(result); - EXPECT_EQ(result.error(), "Can't override settings for log channel SomeChannel: invalid channel"); -} - -TEST_F(LoggerInitTest, LogSizeAndHourRotationCannotBeZero) -{ - std::vector const keys{ - "log_rotation_hour_interval", "log_directory_max_size", "log_rotation_size" - }; - - auto const jsonStr = fmt::format( - R"JSON({{ - "{}": 0, - "{}": 0, - "{}": 0 - }})JSON", - keys[0], - keys[1], - keys[2] - ); - - auto const parsingErrors = config_.parse(ConfigFileJson{boost::json::parse(jsonStr).as_object()}); - ASSERT_EQ(parsingErrors->size(), 3); - for (std::size_t i = 0; i < parsingErrors->size(); ++i) { - EXPECT_EQ( - (*parsingErrors)[i].error, - fmt::format("{} Number must be between 1 and {}", keys[i], std::numeric_limits::max()) - ); - } + ASSERT_EQ(getLoggerString(), "tra:Trace - Trace line logged for 'Trace' component\n"); } #ifndef COVERAGE_ENABLED @@ -259,8 +84,8 @@ TEST_F(NoLoggerTest, Basic) { Logger const log{"Trace"}; log.trace() << "Nothing"; - checkEmpty(); + ASSERT_TRUE(getLoggerString().empty()); LogService::fatal() << "Still nothing"; - checkEmpty(); + ASSERT_TRUE(getLoggerString().empty()); } diff --git a/tests/unit/etl/AmendmentBlockHandlerTests.cpp b/tests/unit/etl/AmendmentBlockHandlerTests.cpp index bfc4ff31..7f98b211 100644 --- a/tests/unit/etl/AmendmentBlockHandlerTests.cpp +++ b/tests/unit/etl/AmendmentBlockHandlerTests.cpp @@ -54,5 +54,5 @@ TEST_F(DefaultAmendmentBlockActionTest, Call) { AmendmentBlockHandler::kDEFAULT_AMENDMENT_BLOCK_ACTION(); auto const loggerString = getLoggerString(); - EXPECT_TRUE(loggerString.starts_with("ETL:FTL Can't process new ledgers")) << "LoggerString " << loggerString; + EXPECT_TRUE(loggerString.starts_with("cri:ETL - Can't process new ledgers")) << "LoggerString " << loggerString; } diff --git a/tests/unit/etlng/AmendmentBlockHandlerTests.cpp b/tests/unit/etlng/AmendmentBlockHandlerTests.cpp index c66ac84b..c77c4f7f 100644 --- a/tests/unit/etlng/AmendmentBlockHandlerTests.cpp +++ b/tests/unit/etlng/AmendmentBlockHandlerTests.cpp @@ -65,5 +65,5 @@ TEST_F(DefaultAmendmentBlockActionNgTest, Call) { AmendmentBlockHandler::kDEFAULT_AMENDMENT_BLOCK_ACTION(); auto const loggerString = getLoggerString(); - EXPECT_TRUE(loggerString.starts_with("ETL:FTL Can't process new ledgers")) << "LoggerString " << loggerString; + EXPECT_TRUE(loggerString.starts_with("cri:ETL - Can't process new ledgers")) << "LoggerString " << loggerString; } diff --git a/tests/unit/rpc/RPCHelpersTests.cpp b/tests/unit/rpc/RPCHelpersTests.cpp index f607fa89..fed88fec 100644 --- a/tests/unit/rpc/RPCHelpersTests.cpp +++ b/tests/unit/rpc/RPCHelpersTests.cpp @@ -1333,14 +1333,14 @@ INSTANTIATE_TEST_SUITE_P( RPCHelpersLogDurationTests, RPCHelpersLogDurationTest, testing::Values( - RPCHelpersLogDurationTestBundle{"ShortDurationLogsAsInfo", std::chrono::milliseconds(500), "RPC:NFO", true}, + RPCHelpersLogDurationTestBundle{"ShortDurationLogsAsInfo", std::chrono::milliseconds(500), "inf:RPC ", true}, RPCHelpersLogDurationTestBundle{ "MediumDurationLogsAsWarning", std::chrono::milliseconds(5000), - "RPC:WRN", + "war:RPC ", true }, - RPCHelpersLogDurationTestBundle{"LongDurationLogsAsError", std::chrono::milliseconds(15000), "RPC:ERR", true} + RPCHelpersLogDurationTestBundle{"LongDurationLogsAsError", std::chrono::milliseconds(15000), "err:RPC ", true} ), tests::util::kNAME_GENERATOR ); diff --git a/tests/unit/util/ScopeGuardTests.cpp b/tests/unit/util/ScopeGuardTests.cpp new file mode 100644 index 00000000..b6cad2cc --- /dev/null +++ b/tests/unit/util/ScopeGuardTests.cpp @@ -0,0 +1,32 @@ +//------------------------------------------------------------------------------ +/* + 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. +*/ +//============================================================================== + +#include "util/ScopeGuard.hpp" + +#include +#include + +TEST(ScopeGuardTest, IsCalled) +{ + testing::StrictMock> mockFunction; + EXPECT_CALL(mockFunction, Call()); + { + util::ScopeGuard guard([&mockFunction] { mockFunction.Call(); }); + } +}