diff --git a/CMakeLists.txt b/CMakeLists.txt index bd19926d..2e7ad20a 100644 --- a/CMakeLists.txt +++ b/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") diff --git a/nano/core_test/conflicts.cpp b/nano/core_test/conflicts.cpp index d6521949..1ce7cf4d 100644 --- a/nano/core_test/conflicts.cpp +++ b/nano/core_test/conflicts.cpp @@ -2,6 +2,8 @@ #include #include +using namespace std::chrono_literals; + TEST (conflicts, start_stop) { nano::system system (24000, 1); diff --git a/nano/core_test/logger.cpp b/nano/core_test/logger.cpp index 5af98af3..6175a533 100644 --- a/nano/core_test/logger.cpp +++ b/nano/core_test/logger.cpp @@ -1,6 +1,7 @@ #include #include #include +#include #include #include #include @@ -92,29 +93,6 @@ TEST (logging, upgrade_v6_v7) ASSERT_EQ (false, tree.get ("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> 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)); diff --git a/nano/core_test/network.cpp b/nano/core_test/network.cpp index b66251ba..6589f295 100644 --- a/nano/core_test/network.cpp +++ b/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 (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 (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 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); diff --git a/nano/core_test/testutil.hpp b/nano/core_test/testutil.hpp index 2fcf5ca3..a15cfda2 100644 --- a/nano/core_test/testutil.hpp +++ b/nano/core_test/testutil.hpp @@ -1,6 +1,8 @@ #pragma once #include +#include +#include #include #include #include @@ -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> console_sink; +}; + namespace util { /** diff --git a/nano/core_test/websocket.cpp b/nano/core_test/websocket.cpp index d084c132..c0e1ecfe 100644 --- a/nano/core_test/websocket.cpp +++ b/nano/core_test/websocket.cpp @@ -26,7 +26,7 @@ namespace std::atomic ack_ready{ false }; /** An optionally blocking websocket client for testing */ -boost::optional 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 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) { diff --git a/nano/lib/CMakeLists.txt b/nano/lib/CMakeLists.txt index 91b80e3a..6337a9b0 100644 --- a/nano/lib/CMakeLists.txt +++ b/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") diff --git a/nano/lib/logger_mt.hpp b/nano/lib/logger_mt.hpp index c5b45639..76900dbc 100644 --- a/nano/lib/logger_mt.hpp +++ b/nano/lib/logger_mt.hpp @@ -1,10 +1,39 @@ #pragma once -#include +#include #include +#include + +#include #include #include +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 const & manip) +{ + // Needs to match order in the severity_level enum + static std::array strings = { + "", + "Error: " + }; + + nano::severity_level level = manip.get (); + assert (static_cast (level) < strings.size ()); + strm << strings[static_cast (level)]; + return strm; +} + namespace nano { // A wrapper around a boost logger object to allow minimum @@ -24,9 +53,9 @@ private: } template - 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 @@ private: public: logger_mt () = default; + /** * @param min_log_delta_a The minimum time between successive output */ @@ -48,19 +78,30 @@ public: /* * @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 + void always_log (nano::severity_level severity_level, LogItems &&... log_items) + { + output (severity_level, std::forward (log_items)...); + } + + /* + * @param log_items A collection of objects with overloaded operator<< to be output to the log file. */ template void always_log (LogItems &&... log_items) { - output (std::forward (log_items)...); + always_log (nano::severity_level::normal, std::forward (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 - 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 @@ public: { last_log_time = time_now; lk.unlock (); - output (std::forward (log_items)...); + output (severity_level, std::forward (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 + bool try_log (LogItems &&... log_items) + { + return try_log (nano::severity_level::normal, std::forward (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 boost_logger_mt; }; } diff --git a/nano/lib/plat/windows/perms.cpp b/nano/lib/plat/windows/perms.cpp index bee8c85f..fc293a89 100644 --- a/nano/lib/plat/windows/perms.cpp +++ b/nano/lib/plat/windows/perms.cpp @@ -3,6 +3,7 @@ #include #include +#include #include #include @@ -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; +} diff --git a/nano/lib/plat/windows/registry.cpp b/nano/lib/plat/windows/registry.cpp new file mode 100644 index 00000000..bd10504e --- /dev/null +++ b/nano/lib/plat/windows/registry.cpp @@ -0,0 +1,16 @@ +#include + +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; +} +} diff --git a/nano/lib/utility.hpp b/nano/lib/utility.hpp index d26042c5..19da371a 100644 --- a/nano/lib/utility.hpp +++ b/nano/lib/utility.hpp @@ -67,6 +67,16 @@ void set_secure_perm_directory (boost::filesystem::path const & path, boost::sys void set_secure_perm_file (boost::filesystem::path const & path); void set_secure_perm_file (boost::filesystem::path const & path, boost::system::error_code & ec); +/* + * Function to check if running Windows as an administrator + */ +bool is_windows_elevated (); + +/* + * Function to check if the Windows Event log registry key exists + */ +bool event_log_reg_entry_exists (); + /* * Functions for understanding the role of the current thread */ diff --git a/nano/nano_node/entry.cpp b/nano/nano_node/entry.cpp index 9fc7e284..5f065185 100644 --- a/nano/nano_node/entry.cpp +++ b/nano/nano_node/entry.cpp @@ -90,6 +90,7 @@ int main (int argc, char * const * argv) ("debug_opencl", "OpenCL work generation") ("debug_profile_verify", "Profile work verification") ("debug_profile_kdf", "Profile kdf function") + ("debug_sys_logging", "Test the system logger") ("debug_verify_profile", "Profile signature verification") ("debug_verify_profile_batch", "Profile batch signature verification") ("debug_profile_bootstrap", "Profile bootstrap style blocks processing (at least 10GB of free storage space required)") @@ -1004,6 +1005,18 @@ int main (int argc, char * const * argv) } std::cout << "Total cemented block count: " << sum << std::endl; } + else if (vm.count ("debug_sys_logging")) + { +#ifdef BOOST_WINDOWS + if (!nano::event_log_reg_entry_exists () && !nano::is_windows_elevated ()) + { + std::cerr << "The event log requires the HKEY_LOCAL_MACHINE\\SYSTEM\\CurrentControlSet\\Services\\EventLog\\Nano\\Nano registry entry, run again as administator to create it.\n"; + return 1; + } +#endif + nano::inactive_node node (data_path); + node.node->logger.always_log (nano::severity_level::error, "Testing system logger"); + } else if (vm.count ("version")) { if (NANO_VERSION_PATCH == 0) diff --git a/nano/node/CMakeLists.txt b/nano/node/CMakeLists.txt index 986a70da..96c2d21e 100644 --- a/nano/node/CMakeLists.txt +++ b/nano/node/CMakeLists.txt @@ -2,6 +2,7 @@ if (${CMAKE_SYSTEM_NAME} MATCHES "Darwin") # No opencl elseif (${CMAKE_SYSTEM_NAME} MATCHES "Windows") set (platform_sources plat/windows/openclapi.cpp) + set (psapi_lib Psapi) elseif (${CMAKE_SYSTEM_NAME} MATCHES "Linux") set (platform_sources plat/posix/openclapi.cpp) elseif (${CMAKE_SYSTEM_NAME} MATCHES "FreeBSD") @@ -101,6 +102,7 @@ target_link_libraries (node Boost::thread Boost::boost ${CMAKE_DL_LIBS} + ${psapi_lib} ) target_compile_definitions(node diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 27b19950..5ea716a5 100644 --- a/nano/node/blockprocessor.cpp +++ b/nano/node/blockprocessor.cpp @@ -296,7 +296,7 @@ void nano::block_processor::process_batch (std::unique_lock & lock_a std::vector rollback_list; if (node.ledger.rollback (transaction, successor->hash (), rollback_list)) { - node.logger.always_log (boost::str (boost::format ("Failed to roll back %1% because it or a successor was confirmed") % successor->hash ().to_string ())); + node.logger.always_log (nano::severity_level::error, boost::str (boost::format ("Failed to roll back %1% because it or a successor was confirmed") % successor->hash ().to_string ())); } else { diff --git a/nano/node/logging.cpp b/nano/node/logging.cpp index 47ff1d90..712eb932 100644 --- a/nano/node/logging.cpp +++ b/nano/node/logging.cpp @@ -1,10 +1,21 @@ +#include #include #include #include #include #include +#include #include +#ifdef BOOST_WINDOWS +#include +#else +#define BOOST_LOG_USE_NATIVE_SYSLOG +#include +#endif + +BOOST_LOG_ATTRIBUTE_KEYWORD (severity, "Severity", nano::severity_level) + boost::shared_ptr> nano::logging::file_sink; std::atomic_flag nano::logging::logging_already_added ATOMIC_FLAG_INIT; @@ -13,12 +24,49 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) if (!logging_already_added.test_and_set ()) { boost::log::add_common_attributes (); + auto format = boost::log::expressions::stream << boost::log::expressions::attr ("Severity") << boost::log::expressions::smessage; + auto format_with_timestamp = boost::log::expressions::stream << "[" << boost::log::expressions::attr ("TimeStamp") << "]: " << boost::log::expressions::attr ("Severity") << boost::log::expressions::smessage; + if (log_to_cerr ()) { - boost::log::add_console_log (std::cerr, boost::log::keywords::format = "[%TimeStamp%]: %Message%"); + boost::log::add_console_log (std::cerr, boost::log::keywords::format = format_with_timestamp); } + + nano::network_constants network_constants; + if (!network_constants.is_test_network ()) + { +#ifdef BOOST_WINDOWS + if (nano::event_log_reg_entry_exists () || nano::is_windows_elevated ()) + { + static auto event_sink = boost::make_shared> (boost::log::keywords::log_name = "Nano", boost::log::keywords::log_source = "Nano"); + event_sink->set_formatter (format); + + // Currently only mapping sys log errors + boost::log::sinks::event_log::custom_event_type_mapping mapping ("Severity"); + mapping[nano::severity_level::error] = boost::log::sinks::event_log::error; + event_sink->locked_backend ()->set_event_type_mapper (mapping); + + // Only allow messages or error or greater severity to the event log + event_sink->set_filter (severity >= nano::severity_level::error); + boost::log::core::get ()->add_sink (event_sink); + } +#else + static auto sys_sink = boost::make_shared> (boost::log::keywords::facility = boost::log::sinks::syslog::user, boost::log::keywords::use_impl = boost::log::sinks::syslog::impl_types::native); + sys_sink->set_formatter (format); + + // Currently only mapping sys log errors + boost::log::sinks::syslog::custom_severity_mapping mapping ("Severity"); + mapping[nano::severity_level::error] = boost::log::sinks::syslog::error; + sys_sink->locked_backend ()->set_severity_mapper (mapping); + + // Only allow messages or error or greater severity to the sys log + sys_sink->set_filter (severity >= nano::severity_level::error); + boost::log::core::get ()->add_sink (sys_sink); +#endif + } + auto path = application_path_a / "log"; - file_sink = boost::log::add_file_log (boost::log::keywords::target = path, boost::log::keywords::file_name = path / "log_%Y-%m-%d_%H-%M-%S.%N.log", boost::log::keywords::rotation_size = rotation_size, boost::log::keywords::auto_flush = flush, boost::log::keywords::scan_method = boost::log::sinks::file::scan_method::scan_matching, boost::log::keywords::max_size = max_size, boost::log::keywords::format = "[%TimeStamp%]: %Message%"); + file_sink = boost::log::add_file_log (boost::log::keywords::target = path, boost::log::keywords::file_name = path / "log_%Y-%m-%d_%H-%M-%S.%N.log", boost::log::keywords::rotation_size = rotation_size, boost::log::keywords::auto_flush = flush, boost::log::keywords::scan_method = boost::log::sinks::file::scan_method::scan_matching, boost::log::keywords::max_size = max_size, boost::log::keywords::format = format_with_timestamp); } } diff --git a/nano/node/logging.hpp b/nano/node/logging.hpp index 397430ae..98da85fa 100644 --- a/nano/node/logging.hpp +++ b/nano/node/logging.hpp @@ -11,11 +11,9 @@ #define FATAL_LOG_PREFIX "FATAL ERROR: " -using namespace std::chrono; - namespace nano { -class logging +class logging final { public: nano::error serialize_json (nano::jsonconfig &) const; diff --git a/nano/slow_test/node.cpp b/nano/slow_test/node.cpp index b963aaec..c711828f 100644 --- a/nano/slow_test/node.cpp +++ b/nano/slow_test/node.cpp @@ -6,6 +6,8 @@ #include +using namespace std::chrono_literals; + TEST (system, generate_mass_activity) { nano::system system (24000, 1);