Special log formatter for running tests

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;

nano/lib/logging.cpp

@@ -4,6 +4,7 @@
 
 #include <fmt/chrono.h>
 #include <spdlog/cfg/env.h>
+#include <spdlog/pattern_formatter.h>
 #include <spdlog/sinks/basic_file_sink.h>
 #include <spdlog/sinks/rotating_file_sink.h>
 #include <spdlog/sinks/stdout_color_sinks.h>
@@ -24,12 +25,102 @@ nano::nlogger & nano::default_logger ()
  * nlogger
  */
 
-bool nano::nlogger::global_initialized;
-nano::log_config nano::nlogger::global_config;
-std::vector<spdlog::sink_ptr> nano::nlogger::global_sinks;
+bool nano::nlogger::global_initialized{ false };
+nano::log_config nano::nlogger::global_config{};
+std::vector<spdlog::sink_ptr> 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<std::string (nano::log::type tag, std::string identifier)> 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 <node identifier, tag>
+std::pair<std::string_view, std::string_view> 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<custom_flag_formatter> clone () const override
+	{
+		return spdlog::details::make_unique<identifier_formatter_flag> ();
+	}
+};
+
+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<custom_flag_formatter> clone () const override
+	{
+		return spdlog::details::make_unique<tag_formatter_flag> ();
+	}
+};
+}
+
+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<spdlog::pattern_formatter> ();
+	formatter->add_flag<identifier_formatter_flag> ('i');
+	formatter->add_flag<tag_formatter_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<spdlog::logger> ("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<spdlog::logger> nano::nlogger::make_logger (nano::log::type tag)
 {
-	auto spd_logger = std::make_shared<spdlog::logger> (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<spdlog::logger> (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;
 }
 

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<nano::log::type, nano::log::detail>;
 	std::map<logger_id_t, nano::log::level> 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<spdlog::sink_ptr> global_sinks;
+	static std::function<std::string (nano::log::type tag, std::string identifier)> global_name_formatter;
+
+	static void initialize_common (nano::log_config const &);
 
 public:
 	template <class... Args>

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");

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);

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;

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);