Add severity logging levels, and send errors to syslog/Event Viewer (incl failed rollbacks for confirmed blocks)

CMakeLists.txt

@@ -37,6 +37,7 @@ set(USING_TSAN (NANO_TSAN OR RAIBLOCKS_TSAN))
 find_package(Threads)
 
 if (WIN32)
+	find_library (PSAPI Psapi)
 	add_definitions(-D_WIN32_WINNT=0x0600
 					-DWINVER=0x0600
 					-DWIN32_LEAN_AND_MEAN
@@ -430,7 +431,10 @@ if (NANO_GUI OR RAIBLOCKS_GUI)
 		else ()
 			set (WIN_REDIST vc_redist.x86.exe)
 		endif ()
-		set (CPACK_NSIS_EXTRA_INSTALL_COMMANDS "ExecWait '\\\"$INSTDIR\\\\${WIN_REDIST}\\\" /quiet /norestart'")
+		set (CPACK_NSIS_EXTRA_INSTALL_COMMANDS "ExecWait '\\\"$INSTDIR\\\\${WIN_REDIST}\\\" /quiet /norestart'
+												WriteRegDWORD HKLM 'SYSTEM\\\\CurrentControlSet\\\\Services\\\\EventLog\\\\Nano\\\\Nano' 'TypesSupported' '0x7'
+												WriteRegStr HKLM 'SYSTEM\\\\CurrentControlSet\\\\Services\\\\EventLog\\\\Nano\\\\Nano' 'EventMessageFile' '$INSTDIR\\\\nano_wallet.exe'")
+		set (CPACK_NSIS_EXTRA_UNINSTALL_COMMANDS "DeleteRegKey HKLM 'SYSTEM\\\\CurrentControlSet\\\\Services\\\\EventLog\\\\Nano'")
 		set (CPACK_NSIS_MUI_ICON ${CMAKE_SOURCE_DIR}/Nano.ico)
 		set (CPACK_NSIS_DISPLAY_NAME "Nano")
 		set (CPACK_PACKAGE_NAME "Nano_Installer")

nano/core_test/conflicts.cpp

@@ -2,6 +2,8 @@
 #include <nano/core_test/testutil.hpp>
 #include <nano/node/testing.hpp>
 
+using namespace std::chrono_literals;
+
 TEST (conflicts, start_stop)
 {
 	nano::system system (24000, 1);

nano/core_test/logger.cpp

@@ -1,6 +1,7 @@
 #include <boost/log/utility/setup/console.hpp>
 #include <chrono>
 #include <gtest/gtest.h>
+#include <nano/core_test/testutil.hpp>
 #include <nano/node/logging.hpp>
 #include <nano/secure/utility.hpp>
 #include <regex>
@@ -92,29 +93,6 @@ TEST (logging, upgrade_v6_v7)
 	ASSERT_EQ (false, tree.get<bool> ("network_timeout_logging_value"));
 }
 
-namespace
-{
-class boost_log_cerr_redirect
-{
-public:
-	boost_log_cerr_redirect (std::streambuf * new_buffer) :
-	old (std::cerr.rdbuf (new_buffer))
-	{
-		console_sink = (boost::log::add_console_log (std::cerr, boost::log::keywords::format = "%Message%"));
-	}
-
-	~boost_log_cerr_redirect ()
-	{
-		std::cerr.rdbuf (old);
-		boost::log::core::get ()->remove_sink (console_sink);
-	}
-
-private:
-	std::streambuf * old;
-	boost::shared_ptr<boost::log::sinks::synchronous_sink<boost::log::sinks::text_ostream_backend>> console_sink;
-};
-}
-
 TEST (logger, changing_time_interval)
 {
 	auto path1 (nano::unique_path ());
@@ -133,7 +111,7 @@ TEST (logger, try_log)
 {
 	auto path1 (nano::unique_path ());
 	std::stringstream ss;
-	boost_log_cerr_redirect redirect_cerr (ss.rdbuf ());
+	nano::boost_log_cerr_redirect redirect_cerr (ss.rdbuf ());
 	nano::logger_mt my_logger (100ms);
 	auto output1 = "logger.try_log1";
 	auto error (my_logger.try_log (output1));
@@ -158,7 +136,7 @@ TEST (logger, always_log)
 {
 	auto path1 (nano::unique_path ());
 	std::stringstream ss;
-	boost_log_cerr_redirect redirect_cerr (ss.rdbuf ());
+	nano::boost_log_cerr_redirect redirect_cerr (ss.rdbuf ());
 	nano::logger_mt my_logger (20s); // Make time interval effectively unreachable
 	auto output1 = "logger.always_log1";
 	auto error (my_logger.try_log (output1));

nano/core_test/network.cpp

@@ -1951,6 +1951,82 @@ TEST (confirmation_height, all_block_types)
 	ASSERT_EQ (node->ledger.stats.count (nano::stat::type::confirmation_height, nano::stat::detail::blocks_confirmed, nano::stat::dir::in), 15);
 }
 
+/* Bulk of the this test was taken from the node.fork_flip test */
+TEST (confirmation_height, conflict_rollback_cemented)
+{
+	nano::system system (24000, 2);
+	auto & node1 (*system.nodes[0]);
+	auto & node2 (*system.nodes[1]);
+	ASSERT_EQ (1, node1.network.size ());
+	nano::keypair key1;
+	nano::genesis genesis;
+	auto send1 (std::make_shared<nano::send_block> (genesis.hash (), key1.pub, nano::genesis_amount - 100, nano::test_genesis_key.prv, nano::test_genesis_key.pub, system.work.generate (genesis.hash ())));
+	nano::publish publish1 (send1);
+	nano::keypair key2;
+	auto send2 (std::make_shared<nano::send_block> (genesis.hash (), key2.pub, nano::genesis_amount - 100, nano::test_genesis_key.prv, nano::test_genesis_key.pub, system.work.generate (genesis.hash ())));
+	nano::publish publish2 (send2);
+	auto channel1 (node1.network.udp_channels.create (node1.network.endpoint ()));
+	node1.process_message (publish1, channel1);
+	node1.block_processor.flush ();
+	auto channel2 (node2.network.udp_channels.create (node1.network.endpoint ()));
+	node2.process_message (publish2, channel2);
+	node2.block_processor.flush ();
+	ASSERT_EQ (1, node1.active.size ());
+	ASSERT_EQ (1, node2.active.size ());
+	system.wallet (0)->insert_adhoc (nano::test_genesis_key.prv);
+	node1.process_message (publish2, channel1);
+	node1.block_processor.flush ();
+	node2.process_message (publish1, channel2);
+	node2.block_processor.flush ();
+	std::unique_lock<std::mutex> lock (node2.active.mutex);
+	auto conflict (node2.active.roots.find (nano::qualified_root (genesis.hash (), genesis.hash ())));
+	ASSERT_NE (node2.active.roots.end (), conflict);
+	auto votes1 (conflict->election);
+	ASSERT_NE (nullptr, votes1);
+	ASSERT_EQ (1, votes1->last_votes.size ());
+	lock.unlock ();
+	// Force blocks to be cemented on both nodes
+	{
+		auto transaction (system.nodes[0]->store.tx_begin_write ());
+		ASSERT_TRUE (node1.store.block_exists (transaction, publish1.block->hash ()));
+
+		nano::account_info info;
+		node1.store.account_get (transaction, nano::genesis_account, info);
+		info.confirmation_height = 2;
+		node1.store.account_put (transaction, nano::genesis_account, info);
+	}
+	{
+		auto transaction (system.nodes[1]->store.tx_begin_write ());
+		ASSERT_TRUE (node2.store.block_exists (transaction, publish2.block->hash ()));
+
+		nano::account_info info;
+		node2.store.account_get (transaction, nano::genesis_account, info);
+		info.confirmation_height = 2;
+		node1.store.account_put (transaction, nano::genesis_account, info);
+	}
+
+	std::stringstream ss;
+	nano::boost_log_cerr_redirect redirect_cerr (ss.rdbuf ());
+
+	auto rollback_log_entry = boost::str (boost::format ("Failed to roll back %1%") % send2->hash ().to_string ());
+	system.deadline_set (10s);
+	auto done (false);
+	while (!done)
+	{
+		ASSERT_NO_ERROR (system.poll ());
+		done = (ss.str ().find (rollback_log_entry) != std::string::npos);
+	}
+	auto transaction1 (system.nodes[0]->store.tx_begin_read ());
+	auto transaction2 (system.nodes[1]->store.tx_begin_read ());
+	lock.lock ();
+	auto winner (*votes1->tally (transaction2).begin ());
+	ASSERT_EQ (*publish1.block, *winner.second);
+	ASSERT_EQ (nano::genesis_amount - 100, winner.first);
+	ASSERT_TRUE (node1.store.block_exists (transaction1, publish1.block->hash ()));
+	ASSERT_TRUE (node2.store.block_exists (transaction2, publish2.block->hash ()));
+	ASSERT_FALSE (node2.store.block_exists (transaction2, publish1.block->hash ()));
+}
+
 TEST (bootstrap, tcp_listener_timeout_empty)
 {
 	nano::system system (24000, 1);

nano/core_test/testutil.hpp

@@ -1,6 +1,8 @@
 #pragma once
 
 #include <atomic>
+#include <boost/log/sources/logger.hpp>
+#include <boost/log/utility/setup/console.hpp>
 #include <boost/multiprecision/cpp_int.hpp>
 #include <condition_variable>
 #include <mutex>
@@ -41,6 +43,26 @@ extern nano::uint256_union const & genesis_account;
 extern nano::uint256_union const & burn_account;
 extern nano::uint128_t const & genesis_amount;
 
+class boost_log_cerr_redirect
+{
+public:
+	boost_log_cerr_redirect (std::streambuf * new_buffer) :
+	old (std::cerr.rdbuf (new_buffer))
+	{
+		console_sink = (boost::log::add_console_log (std::cerr, boost::log::keywords::format = "%Message%"));
+	}
+
+	~boost_log_cerr_redirect ()
+	{
+		std::cerr.rdbuf (old);
+		boost::log::core::get ()->remove_sink (console_sink);
+	}
+
+private:
+	std::streambuf * old;
+	boost::shared_ptr<boost::log::sinks::synchronous_sink<boost::log::sinks::text_ostream_backend>> console_sink;
+};
+
 namespace util
 {
 	/**

nano/core_test/websocket.cpp

@@ -26,7 +26,7 @@ namespace
 std::atomic<bool> ack_ready{ false };
 
 /** An optionally blocking websocket client for testing */
-boost::optional<std::string> websocket_test_call (std::string host, std::string port, std::string message_a, bool await_ack, bool await_response, const seconds response_deadline = 5s)
+boost::optional<std::string> websocket_test_call (std::string host, std::string port, std::string message_a, bool await_ack, bool await_response, const std::chrono::seconds response_deadline = 5s)
 {
 	if (await_ack)
 	{

nano/lib/CMakeLists.txt

@@ -1,7 +1,7 @@
 if (${CMAKE_SYSTEM_NAME} MATCHES "Darwin")
 	set (platform_sources plat/default/priority.cpp plat/posix/perms.cpp plat/darwin/thread_role.cpp)
 elseif (${CMAKE_SYSTEM_NAME} MATCHES "Windows")
-	set (platform_sources plat/windows/priority.cpp plat/windows/perms.cpp plat/windows/thread_role.cpp)
+	set (platform_sources plat/windows/priority.cpp plat/windows/perms.cpp plat/windows/registry.cpp plat/windows/thread_role.cpp)
 elseif (${CMAKE_SYSTEM_NAME} MATCHES "Linux")
 	set (platform_sources plat/linux/priority.cpp plat/posix/perms.cpp plat/linux/thread_role.cpp)
 elseif (${CMAKE_SYSTEM_NAME} MATCHES "FreeBSD")

nano/lib/logger_mt.hpp

@@ -1,10 +1,39 @@
 #pragma once
 
-#include <boost/log/sources/logger.hpp>
+#include <boost/log/sources/severity_logger.hpp>
 #include <boost/log/trivial.hpp>
+#include <boost/log/utility/manipulators/to_log.hpp>
+
+#include <array>
 #include <chrono>
 #include <mutex>
 
+namespace nano
+{
+enum class severity_level
+{
+	normal = 0,
+	error
+};
+}
+
+// Attribute value tag type
+struct severity_tag;
+
+inline boost::log::formatting_ostream & operator<< (boost::log::formatting_ostream & strm, boost::log::to_log_manip<nano::severity_level, severity_tag> const & manip)
+{
+	// Needs to match order in the severity_level enum
+	static std::array<const char *, 2> strings = {
+		"",
+		"Error: "
+	};
+
+	nano::severity_level level = manip.get ();
+	assert (static_cast<int> (level) < strings.size ());
+	strm << strings[static_cast<int> (level)];
+	return strm;
+}
+
 namespace nano
 {
 // A wrapper around a boost logger object to allow minimum
@@ -24,9 +53,9 @@ class logger_mt
 	}
 
 	template <typename... LogItems>
-	void output (LogItems &&... log_items)
+	void output (nano::severity_level severity_level, LogItems &&... log_items)
 	{
-		boost::log::record rec = boost_logger_mt.open_record ();
+		boost::log::record rec = boost_logger_mt.open_record (boost::log::keywords::severity = severity_level);
 		if (rec)
 		{
 			boost::log::record_ostream strm (rec);
@@ -38,6 +67,7 @@ class logger_mt
 
 public:
 	logger_mt () = default;
+
 	/**
 	 * @param min_log_delta_a The minimum time between successive output
 	 */
@@ -48,19 +78,30 @@ class logger_mt
 
 	/*
 	 * @param log_items A collection of objects with overloaded operator<< to be output to the log file
+	 * @params severity_level The severity level that this log message should have.
+	 */
+	template <typename... LogItems>
+	void always_log (nano::severity_level severity_level, LogItems &&... log_items)
+	{
+		output (severity_level, std::forward<LogItems> (log_items)...);
+	}
+
+	/*
+	 * @param log_items A collection of objects with overloaded operator<< to be output to the log file.
 	 */
 	template <typename... LogItems>
 	void always_log (LogItems &&... log_items)
 	{
-		output (std::forward<LogItems> (log_items)...);
+		always_log (nano::severity_level::normal, std::forward<LogItems> (log_items)...);
 	}
 
 	/*
 	 * @param log_items Output to the log file if the last write was over min_log_delta time ago.
-	 * @return true if the log was successful
+	 * @params severity_level The severity level that this log message should have.
+	 * @return true if nothing was logged
 	 */
 	template <typename... LogItems>
-	bool try_log (LogItems &&... log_items)
+	bool try_log (nano::severity_level severity_level, LogItems &&... log_items)
 	{
 		auto error (true);
 		auto time_now = std::chrono::steady_clock::now ();
@@ -69,17 +110,27 @@ class logger_mt
 		{
 			last_log_time = time_now;
 			lk.unlock ();
-			output (std::forward<LogItems> (log_items)...);
+			output (severity_level, std::forward<LogItems> (log_items)...);
 			error = false;
 		}
 		return error;
 	}
 
+	/*
+	 * @param log_items Output to the log file if the last write was over min_log_delta time ago.
+	 * @return true if nothing was logged
+	 */
+	template <typename... LogItems>
+	bool try_log (LogItems &&... log_items)
+	{
+		return try_log (nano::severity_level::normal, std::forward<LogItems> (log_items)...);
+	}
+
 	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;
+	boost::log::sources::severity_logger_mt<severity_level> boost_logger_mt;
 };
 }

nano/lib/plat/windows/perms.cpp

@@ -3,6 +3,7 @@
 #include <nano/lib/utility.hpp>
 
 #include <io.h>
+#include <processthreadsapi.h>
 #include <sys/stat.h>
 #include <sys/types.h>
 
@@ -33,3 +34,23 @@ void nano::set_secure_perm_file (boost::filesystem::path const & path, boost::sy
 {
 	boost::filesystem::permissions (path, boost::filesystem::owner_read | boost::filesystem::owner_write, ec);
 }
+
+bool nano::is_windows_elevated ()
+{
+	bool is_elevated = false;
+	HANDLE h_token = nullptr;
+	if (OpenProcessToken (GetCurrentProcess (), TOKEN_QUERY, &h_token))
+	{
+		TOKEN_ELEVATION elevation;
+		DWORD cb_size = sizeof (TOKEN_ELEVATION);
+		if (GetTokenInformation (h_token, TokenElevation, &elevation, sizeof (elevation), &cb_size))
+		{
+			is_elevated = elevation.TokenIsElevated;
+		}
+	}
+	if (h_token)
+	{
+		CloseHandle (h_token);
+	}
+	return is_elevated;
+}

nano/lib/plat/windows/registry.cpp

@@ -0,0 +1,16 @@
+#include <windows.h>
+
+namespace nano
+{
+bool event_log_reg_entry_exists ()
+{
+	HKEY h_key;
+	auto res = RegOpenKeyExW (HKEY_LOCAL_MACHINE, L"SYSTEM\\CurrentControlSet\\Services\\EventLog\\Nano\\Nano", 0, KEY_READ, &h_key);
+	auto found_key = (res == ERROR_SUCCESS);
+	if (found_key)
+	{
+		RegCloseKey (h_key);
+	}
+	return found_key;
+}
+}