Fix TSAN warning with nano::logger_mt (#1892)

* Protect last_log_time with a mutex

* Make changes to nano_wallet

nano/core_test/processor_service.cpp

@@ -9,9 +9,9 @@
 
 TEST (processor_service, bad_send_signature)
 {
-	nano::logging logging;
+	nano::logger_mt logger;
 	bool init (false);
-	nano::mdb_store store (init, logging, nano::unique_path ());
+	nano::mdb_store store (init, logger, nano::unique_path ());
 	ASSERT_FALSE (init);
 	nano::stat stats;
 	nano::ledger ledger (store, stats);
@@ -28,9 +28,9 @@ TEST (processor_service, bad_send_signature)
 
 TEST (processor_service, bad_receive_signature)
 {
-	nano::logging logging;
+	nano::logger_mt logger;
 	bool init (false);
-	nano::mdb_store store (init, logging, nano::unique_path ());
+	nano::mdb_store store (init, logger, nano::unique_path ());
 	ASSERT_FALSE (init);
 	nano::stat stats;
 	nano::ledger ledger (store, stats);

nano/core_test/versioning.cpp

@@ -10,9 +10,9 @@ TEST (versioning, account_info_v1)
 	nano::open_block open (1, 2, 3, nullptr);
 	nano::account_info_v1 v1 (open.hash (), open.hash (), 3, 4);
 	{
-		nano::logging logging;
+		nano::logger_mt logger;
 		auto error (false);
-		nano::mdb_store store (error, logging, file);
+		nano::mdb_store store (error, logger, file);
 		ASSERT_FALSE (error);
 		auto transaction (store.tx_begin (true));
 		nano::block_sideband sideband (nano::block_type::open, 0, 0, 0, 0, 0);
@@ -22,9 +22,9 @@ TEST (versioning, account_info_v1)
 		store.version_put (transaction, 1);
 	}
 
-	nano::logging logging;
+	nano::logger_mt logger;
 	auto error (false);
-	nano::mdb_store store (error, logging, file);
+	nano::mdb_store store (error, logger, file);
 	ASSERT_FALSE (error);
 	auto transaction (store.tx_begin ());
 	nano::account_info v_latest;
@@ -46,9 +46,9 @@ TEST (versioning, account_info_v5)
 	nano::open_block open (1, 2, 3, nullptr);
 	nano::account_info_v5 v5 (open.hash (), open.hash (), open.hash (), 3, 4);
 	{
-		nano::logging logging;
+		nano::logger_mt logger;
 		auto error (false);
-		nano::mdb_store store (error, logging, file);
+		nano::mdb_store store (error, logger, file);
 		ASSERT_FALSE (error);
 		auto transaction (store.tx_begin (true));
 		nano::block_sideband sideband (nano::block_type::open, 0, 0, 0, 0, 0);
@@ -58,9 +58,9 @@ TEST (versioning, account_info_v5)
 		store.version_put (transaction, 5);
 	}
 
-	nano::logging logging;
+	nano::logger_mt logger;
 	auto error (false);
-	nano::mdb_store store (error, logging, file);
+	nano::mdb_store store (error, logger, file);
 	ASSERT_FALSE (error);
 	auto transaction (store.tx_begin ());
 	nano::account_info v_latest;
@@ -82,9 +82,9 @@ TEST (versioning, account_info_v13)
 	nano::open_block open (1, 2, 3, nullptr);
 	nano::account_info_v13 v13 (open.hash (), open.hash (), open.hash (), 3, 4, 10, nano::epoch::epoch_0);
 	{
-		nano::logging logging;
+		nano::logger_mt logger;
 		auto error (false);
-		nano::mdb_store store (error, logging, file);
+		nano::mdb_store store (error, logger, file);
 		ASSERT_FALSE (error);
 		auto transaction (store.tx_begin (true));
 		nano::block_sideband sideband (nano::block_type::open, 0, 0, 0, 0, 0);
@@ -94,9 +94,9 @@ TEST (versioning, account_info_v13)
 		store.version_put (transaction, 13);
 	}
 
-	nano::logging logging;
+	nano::logger_mt logger;
 	auto error (false);
-	nano::mdb_store store (error, logging, file);
+	nano::mdb_store store (error, logger, file);
 	ASSERT_FALSE (error);
 	auto transaction (store.tx_begin ());
 	nano::account_info v_latest;

nano/core_test/work_pool.cpp

@@ -69,12 +69,13 @@ TEST (work, opencl)
 {
 	nano::logging logging;
 	logging.init (nano::unique_path ());
+	nano::logger_mt logger;
 	bool error (false);
 	nano::opencl_environment environment (error);
 	ASSERT_FALSE (error);
 	if (!environment.platforms.empty () && !environment.platforms.begin ()->devices.empty ())
 	{
-		auto opencl (nano::opencl_work::create (true, { 0, 0, 16 * 1024 }, logging));
+		auto opencl (nano::opencl_work::create (true, { 0, 0, 16 * 1024 }, logger));
 		if (opencl != nullptr)
 		{
 			nano::work_pool pool (std::numeric_limits<unsigned>::max (), std::chrono::nanoseconds (0), opencl ? [&opencl](nano::uint256_union const & root_a, uint64_t difficulty_a) {

nano/lib/logger_mt.hpp

@@ -3,6 +3,7 @@
 #include <boost/log/sources/logger.hpp>
 #include <boost/log/trivial.hpp>
 #include <chrono>
+#include <mutex>
 
 namespace nano
 {
@@ -36,6 +37,7 @@ class logger_mt
 	}
 
 public:
+	logger_mt () = default;
 	/**
 	 * @param min_log_delta_a The minimum time between successive output
 	 */
@@ -62,18 +64,21 @@ class logger_mt
 	{
 		auto error (true);
 		auto time_now = std::chrono::steady_clock::now ();
+		std::unique_lock<std::mutex> lk (last_log_time_mutex);
 		if (((time_now - last_log_time) > min_log_delta) || last_log_time == std::chrono::steady_clock::time_point{})
 		{
-			output (std::forward<LogItems> (log_items)...);
 			last_log_time = time_now;
+			lk.unlock ();
+			output (std::forward<LogItems> (log_items)...);
 			error = false;
 		}
 		return error;
 	}
 
-	std::chrono::milliseconds min_log_delta;
+	std::chrono::milliseconds min_log_delta{ 0 };
 
 private:
+	std::mutex last_log_time_mutex;
 	std::chrono::steady_clock::time_point last_log_time;
 	boost::log::sources::logger_mt boost_logger_mt;
 };

nano/nano_node/daemon.cpp

@@ -31,8 +31,9 @@ void nano_daemon::daemon::run (boost::filesystem::path const & data_path, nano::
 	if (!error)
 	{
 		config.node.logging.init (data_path);
+		nano::logger_mt logger{ config.node.logging.min_time_between_log_output };
 		boost::asio::io_context io_ctx;
-		auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, config.node.logging));
+		auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, logger));
 		nano::work_pool opencl_work (config.node.work_threads, config.node.pow_sleep_interval, opencl ? [&opencl](nano::uint256_union const & root_a, uint64_t difficulty_a) {
 			return opencl->generate_work (root_a, difficulty_a);
 		}

nano/nano_node/entry.cpp

@@ -373,8 +373,8 @@ int main (int argc, char * const * argv)
 						error |= device >= environment.platforms[platform].devices.size ();
 						if (!error)
 						{
-							nano::logging logging;
-							auto opencl (nano::opencl_work::create (true, { platform, device, threads }, logging));
+							nano::logger_mt logger;
+							auto opencl (nano::opencl_work::create (true, { platform, device, threads }, logger));
 							nano::work_pool work_pool (std::numeric_limits<unsigned>::max (), std::chrono::nanoseconds (0), opencl ? [&opencl](nano::uint256_union const & root_a, uint64_t difficulty_a) {
 								return opencl->generate_work (root_a, difficulty_a);
 							}

nano/nano_wallet/entry.cpp

@@ -246,10 +246,11 @@ int run_wallet (QApplication & application, int argc, char * const * argv, boost
 	{
 		boost::asio::io_context io_ctx;
 		config.node.logging.init (data_path);
+		nano::logger_mt logger{ config.node.logging.min_time_between_log_output };
 		std::shared_ptr<nano::node> node;
 		std::shared_ptr<nano_qt::wallet> gui;
 		nano::set_application_icon (application);
-		auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, config.node.logging));
+		auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, logger));
 		nano::work_pool work (config.node.work_threads, config.node.pow_sleep_interval, opencl ? [&opencl](nano::uint256_union const & root_a, uint64_t difficulty_a) {
 			return opencl->generate_work (root_a, difficulty_a);
 		}

nano/node/cli.cpp

@@ -369,7 +369,7 @@ std::error_code nano::handle_node_options (boost::program_options::variables_map
 			environment.dump (std::cout);
 			std::stringstream stream;
 			environment.dump (stream);
-			node.logging.logger.always_log (stream.str ());
+			node.node->logger.always_log (stream.str ());
 		}
 		else
 		{

nano/node/lmdb.cpp

@@ -773,8 +773,8 @@ nano::store_iterator<nano::account, std::shared_ptr<nano::vote>> nano::mdb_store
 	return nano::store_iterator<nano::account, std::shared_ptr<nano::vote>> (nullptr);
 }
 
-nano::mdb_store::mdb_store (bool & error_a, nano::logging & logging_a, boost::filesystem::path const & path_a, int lmdb_max_dbs, bool drop_unchecked, size_t const batch_size) :
-logging (logging_a),
+nano::mdb_store::mdb_store (bool & error_a, nano::logger_mt & logger_a, boost::filesystem::path const & path_a, int lmdb_max_dbs, bool drop_unchecked, size_t const batch_size) :
+logger (logger_a),
 env (error_a, path_a, lmdb_max_dbs)
 {
 	if (!error_a)
@@ -1183,7 +1183,7 @@ void nano::mdb_store::upgrade_v12_to_v13 (nano::transaction const & transaction_
 			{
 				if (cost >= batch_size)
 				{
-					logging.logger.always_log (boost::str (boost::format ("Upgrading sideband information for account %1%... height %2%") % first.to_account ().substr (0, 24) % std::to_string (height)));
+					logger.always_log (boost::str (boost::format ("Upgrading sideband information for account %1%... height %2%") % first.to_account ().substr (0, 24) % std::to_string (height)));
 					auto tx (boost::polymorphic_downcast<nano::mdb_txn *> (transaction_a.impl.get ()));
 					auto status0 (mdb_txn_commit (*tx));
 					release_assert (status0 == MDB_SUCCESS);
@@ -1216,7 +1216,7 @@ void nano::mdb_store::upgrade_v12_to_v13 (nano::transaction const & transaction_
 	}
 	if (account == not_an_account)
 	{
-		logging.logger.always_log (boost::str (boost::format ("Completed sideband upgrade")));
+		logger.always_log (boost::str (boost::format ("Completed sideband upgrade")));
 		version_put (transaction_a, 13);
 	}
 }
@@ -1242,8 +1242,6 @@ void nano::mdb_store::upgrade_v13_to_v14 (nano::transaction const & transaction_
 		account_put (transaction_a, account_info.first, account_info.second);
 	}
 
-	logging.logger.always_log (boost::str (boost::format ("Completed confirmation height upgrade")));
-
 	nano::uint256_union node_id_mdb_key (3);
 	auto error (mdb_del (env.tx (transaction_a), meta, nano::mdb_val (node_id_mdb_key), nullptr));
 	release_assert (!error || error == MDB_NOTFOUND);

nano/node/lmdb.hpp

@@ -5,8 +5,8 @@
 #include <lmdb/libraries/liblmdb/lmdb.h>
 
 #include <nano/lib/config.hpp>
+#include <nano/lib/logger_mt.hpp>
 #include <nano/lib/numbers.hpp>
-#include <nano/node/logging.hpp>
 #include <nano/secure/blockstore.hpp>
 #include <nano/secure/common.hpp>
 
@@ -145,7 +145,7 @@ class mdb_merge_iterator : public store_iterator_impl<T, U>
 	std::unique_ptr<nano::mdb_iterator<T, U>> impl2;
 };
 
-class logging;
+class logging_mt;
 /**
  * mdb implementation of the block store
  */
@@ -154,7 +154,7 @@ class mdb_store : public block_store
 	friend class nano::block_predecessor_set;
 
 public:
-	mdb_store (bool &, nano::logging &, boost::filesystem::path const &, int lmdb_max_dbs = 128, bool drop_unchecked = false, size_t batch_size = 512);
+	mdb_store (bool &, nano::logger_mt &, boost::filesystem::path const &, int lmdb_max_dbs = 128, bool drop_unchecked = false, size_t batch_size = 512);
 	nano::transaction tx_begin_write () override;
 	nano::transaction tx_begin_read () override;
 	nano::transaction tx_begin (bool write = false) override;
@@ -270,7 +270,7 @@ class mdb_store : public block_store
 	MDB_dbi get_account_db (nano::epoch epoch_a) const;
 	size_t block_successor_offset (nano::transaction const &, MDB_val, nano::block_type) const;
 
-	nano::logging & logging;
+	nano::logger_mt & logger;
 
 	nano::mdb_env env;
 

nano/node/logging.hpp

@@ -62,7 +62,6 @@ class logging
 	uintmax_t max_size{ 128 * 1024 * 1024 };
 	uintmax_t rotation_size{ 4 * 1024 * 1024 };
 	std::chrono::milliseconds min_time_between_log_output{ 5 };
-	nano::logger_mt logger{ min_time_between_log_output };
 	static void release_file_sink ();
 	int json_version () const
 	{

nano/node/node.cpp

@@ -1027,7 +1027,7 @@ flags (flags_a),
 alarm (alarm_a),
 work (work_a),
 logger (config_a.logging.min_time_between_log_output),
-store_impl (std::make_unique<nano::mdb_store> (init_a.block_store_init, config.logging, application_path_a / "data.ldb", config_a.lmdb_max_dbs, !flags.disable_unchecked_drop, flags.sideband_batch_size)),
+store_impl (std::make_unique<nano::mdb_store> (init_a.block_store_init, logger, application_path_a / "data.ldb", config_a.lmdb_max_dbs, !flags.disable_unchecked_drop, flags.sideband_batch_size)),
 store (*store_impl),
 wallets_store_impl (std::make_unique<nano::mdb_wallets_store> (init_a.wallets_store_init, application_path_a / "wallets.ldb", config_a.lmdb_max_dbs)),
 wallets_store (*wallets_store_impl),