From cbda8588cd5ad3431d2a0f85f032a9245da08b75 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Wed, 17 Jan 2024 16:10:08 +0100 Subject: [PATCH] Special log formatter for running tests --- nano/core_test/core_test_main.cc | 2 +- nano/lib/logging.cpp | 116 +++++++++++++++++++++++++++---- nano/lib/logging.hpp | 5 ++ nano/load_test/entry.cpp | 2 +- nano/qt_test/entry.cpp | 2 +- nano/rpc_test/entry.cpp | 2 +- nano/slow_test/entry.cpp | 2 +- 7 files changed, 113 insertions(+), 18 deletions(-) diff --git a/nano/core_test/core_test_main.cc b/nano/core_test/core_test_main.cc index c2f2d221..51e8e816 100644 --- a/nano/core_test/core_test_main.cc +++ b/nano/core_test/core_test_main.cc @@ -19,7 +19,7 @@ void force_nano_dev_network (); GTEST_API_ int main (int argc, char ** argv) { - nano::nlogger::initialize (nano::load_log_config (nano::log_config::tests_default ())); + nano::nlogger::initialize_for_tests (nano::load_log_config (nano::log_config::tests_default ())); nano::set_file_descriptor_limit (OPEN_FILE_DESCRIPTORS_LIMIT); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; diff --git a/nano/lib/logging.cpp b/nano/lib/logging.cpp index aafc1466..68c2ccc2 100644 --- a/nano/lib/logging.cpp +++ b/nano/lib/logging.cpp @@ -4,6 +4,7 @@ #include #include +#include #include #include #include @@ -24,12 +25,102 @@ nano::nlogger & nano::default_logger () * nlogger */ -bool nano::nlogger::global_initialized; -nano::log_config nano::nlogger::global_config; -std::vector nano::nlogger::global_sinks; +bool nano::nlogger::global_initialized{ false }; +nano::log_config nano::nlogger::global_config{}; +std::vector nano::nlogger::global_sinks{}; + +// By default, use only the tag as the logger name, since only one node is running in the process +std::function nano::nlogger::global_name_formatter{ [] (auto tag, auto identifier) { + return std::string{ to_string (tag) }; +} }; void nano::nlogger::initialize (nano::log_config config) { + initialize_common (config); + + global_initialized = true; +} + +// Custom log formatter flags +namespace +{ +/// Takes a qualified identifier in the form `node_identifier::tag` and splits it into a pair of `identifier` and `tag` +/// It is a limitation of spldlog that we cannot attach additional data to the logger, so we have to encode the node identifier in the logger name +/// @returns +std::pair split_qualified_identifier (std::string_view qualified_identifier) +{ + auto pos = qualified_identifier.find ("::"); + debug_assert (pos != std::string_view::npos); // This should never happen, since the default logger name formatter always adds the tag + if (pos == std::string_view::npos) + { + return { std::string_view{}, qualified_identifier }; + } + else + { + return { qualified_identifier.substr (0, pos), qualified_identifier.substr (pos + 2) }; + } +} + +class identifier_formatter_flag : public spdlog::custom_flag_formatter +{ +public: + void format (const spdlog::details::log_msg & msg, const std::tm & tm, spdlog::memory_buf_t & dest) override + { + // Extract identifier and tag from logger name + auto [identifier, tag] = split_qualified_identifier (std::string_view (msg.logger_name.data (), msg.logger_name.size ())); + dest.append (identifier.data (), identifier.data () + identifier.size ()); + } + + std::unique_ptr clone () const override + { + return spdlog::details::make_unique (); + } +}; + +class tag_formatter_flag : public spdlog::custom_flag_formatter +{ +public: + void format (const spdlog::details::log_msg & msg, const std::tm & tm, spdlog::memory_buf_t & dest) override + { + // Extract identifier and tag from logger name + auto [identifier, tag] = split_qualified_identifier (std::string_view (msg.logger_name.data (), msg.logger_name.size ())); + dest.append (tag.data (), tag.data () + tag.size ()); + } + + std::unique_ptr clone () const override + { + return spdlog::details::make_unique (); + } +}; +} + +void nano::nlogger::initialize_for_tests (nano::log_config config) +{ + initialize_common (config); + + // Use tag and identifier as the logger name, since multiple nodes may be running in the same process + global_name_formatter = [] (nano::log::type tag, std::string identifier) { + return fmt::format ("{}::{}", identifier, to_string (tag)); + }; + + auto formatter = std::make_unique (); + formatter->add_flag ('i'); + formatter->add_flag ('n'); + formatter->set_pattern ("[%Y-%m-%d %H:%M:%S.%e] [%i] [%n] [%l] %v"); + + for (auto & sink : global_sinks) + { + // Make deep copy of formatter for each sink + sink->set_formatter (formatter->clone ()); + } + + global_initialized = true; +} + +void nano::nlogger::initialize_common (nano::log_config const & config) +{ + global_config = config; + spdlog::set_automatic_registration (false); spdlog::set_level (to_spdlog_level (config.default_level)); spdlog::cfg::load_env_levels (); @@ -72,7 +163,7 @@ void nano::nlogger::initialize (nano::log_config config) std::filesystem::path log_path{ "log" }; log_path /= filename + ".log"; - nano::default_logger ().info (nano::log::type::logging, "Logging to file: {}", log_path.string ()); + std::cerr << "Logging to file: " << log_path.string () << std::endl; // If either max_size or rotation_count is 0, then disable file rotation if (config.file.max_size == 0 || config.file.rotation_count == 0) @@ -88,11 +179,6 @@ void nano::nlogger::initialize (nano::log_config config) global_sinks.push_back (file_sink); } } - - auto logger = std::make_shared ("default", global_sinks.begin (), global_sinks.end ()); - spdlog::set_default_logger (logger); - - global_initialized = true; } void nano::nlogger::flush () @@ -134,19 +220,23 @@ spdlog::logger & nano::nlogger::get_logger (nano::log::type tag) std::shared_ptr nano::nlogger::make_logger (nano::log::type tag) { - auto spd_logger = std::make_shared (std::string{ to_string (tag) }, global_sinks.begin (), global_sinks.end ()); + auto const & config = global_config; + auto const & sinks = global_sinks; - spdlog::initialize_logger (spd_logger); + auto name = global_name_formatter (tag, identifier); + auto spd_logger = std::make_shared (name, sinks.begin (), sinks.end ()); - if (auto it = global_config.levels.find ({ tag, nano::log::detail::all }); it != global_config.levels.end ()) + if (auto it = config.levels.find ({ tag, nano::log::detail::all }); it != config.levels.end ()) { spd_logger->set_level (to_spdlog_level (it->second)); } else { - spd_logger->set_level (to_spdlog_level (global_config.default_level)); + spd_logger->set_level (to_spdlog_level (config.default_level)); } + spd_logger->flush_on (to_spdlog_level (config.flush_level)); + return spd_logger; } diff --git a/nano/lib/logging.hpp b/nano/lib/logging.hpp index 26df820f..a9b10c66 100644 --- a/nano/lib/logging.hpp +++ b/nano/lib/logging.hpp @@ -24,6 +24,7 @@ private: public: nano::log::level default_level{ nano::log::level::info }; + nano::log::level flush_level{ nano::log::level::error }; using logger_id_t = std::pair; std::map levels{ default_levels (default_level) }; @@ -75,12 +76,16 @@ public: public: static void initialize (nano::log_config); + static void initialize_for_tests (nano::log_config); static void flush (); private: static bool global_initialized; static nano::log_config global_config; static std::vector global_sinks; + static std::function global_name_formatter; + + static void initialize_common (nano::log_config const &); public: template diff --git a/nano/load_test/entry.cpp b/nano/load_test/entry.cpp index ea26bee3..3fe71346 100644 --- a/nano/load_test/entry.cpp +++ b/nano/load_test/entry.cpp @@ -491,7 +491,7 @@ account_info account_info_rpc (boost::asio::io_context & ioc, tcp::resolver::res /** This launches a node and fires a lot of send/recieve RPC requests at it (configurable), then other nodes are tested to make sure they observe these blocks as well. */ int main (int argc, char * const * argv) { - nano::nlogger::initialize (nano::load_log_config (nano::log_config::tests_default ())); + nano::nlogger::initialize_for_tests (nano::load_log_config (nano::log_config::tests_default ())); nano::force_nano_dev_network (); boost::program_options::options_description description ("Command line options"); diff --git a/nano/qt_test/entry.cpp b/nano/qt_test/entry.cpp index 6208cbb2..3ac2f817 100644 --- a/nano/qt_test/entry.cpp +++ b/nano/qt_test/entry.cpp @@ -17,7 +17,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { - nano::nlogger::initialize (nano::load_log_config (nano::log_config::tests_default ())); + nano::nlogger::initialize_for_tests (nano::load_log_config (nano::log_config::tests_default ())); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; QApplication application (argc, argv); diff --git a/nano/rpc_test/entry.cpp b/nano/rpc_test/entry.cpp index 3f814843..06b87f93 100644 --- a/nano/rpc_test/entry.cpp +++ b/nano/rpc_test/entry.cpp @@ -15,7 +15,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { - nano::nlogger::initialize (nano::load_log_config (nano::log_config::tests_default ())); + nano::nlogger::initialize_for_tests (nano::load_log_config (nano::log_config::tests_default ())); nano::force_nano_dev_network (); nano::set_use_memory_pools (false); nano::node_singleton_memory_pool_purge_guard cleanup_guard; diff --git a/nano/slow_test/entry.cpp b/nano/slow_test/entry.cpp index d7cf3c68..cec8cabc 100644 --- a/nano/slow_test/entry.cpp +++ b/nano/slow_test/entry.cpp @@ -14,7 +14,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { - nano::nlogger::initialize (nano::load_log_config (nano::log_config::tests_default ())); + nano::nlogger::initialize_for_tests (nano::load_log_config (nano::log_config::tests_default ())); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; testing::InitGoogleTest (&argc, argv);