Minecon724/dncurrency
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions 1

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

Browse source 
* Add sys logging during erroneous rollbacks

* Formatting

* Add Windows event viewer logging

* Add Psapi to windows build

* Add new windows functions

* Update Windows installer, add prefix to severity level for all log sinks

* Cleanup

* Add test to check failed rollback of cemented block of a successfully elected fork

* Do extra check on windows for the --debug_sys_logging CLI option if it won't work

* Formatting
This commit is contained in:
Wesley Shillingford 2019-05-18 08:49:26 +01:00 • committed by GitHub
commit 6247260e50
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
17 changed files with 285 additions and 42 deletions
Download patch file Download diff file Expand all files Collapse all files

6
CMakeLists.txt
View file

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

2
nano/core_test/conflicts.cpp
View file

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

28
nano/core_test/logger.cpp
View file

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

76
nano/core_test/network.cpp
View file

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

22
nano/core_test/testutil.hpp
View file

@ -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
{
/**

2
nano/core_test/websocket.cpp
View file

@ -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)
{

2
nano/lib/CMakeLists.txt
View file

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

67
nano/lib/logger_mt.hpp
View file

@ -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 @@ private:
}
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 @@ 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 <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 @@ public:
{
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;
};
}

21
nano/lib/plat/windows/perms.cpp
View file

@ -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;
}

16
nano/lib/plat/windows/registry.cpp Normal file
View file

@ -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;
}
}

10
nano/lib/utility.hpp
View file

@ -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
*/

13
nano/nano_node/entry.cpp
View file

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

2
nano/node/CMakeLists.txt
View file

@ -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

2
nano/node/blockprocessor.cpp
View file

@ -296,7 +296,7 @@ void nano::block_processor::process_batch (std::unique_lock<std::mutex> & lock_a
std::vector<nano::block_hash> 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
{

52
nano/node/logging.cpp
View file

@ -1,10 +1,21 @@
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <boost/property_tree/ptree.hpp>
#include <nano/lib/config.hpp>
#include <nano/node/logging.hpp>
#ifdef BOOST_WINDOWS
#include <boost/log/sinks/event_log_backend.hpp>
#else
#define BOOST_LOG_USE_NATIVE_SYSLOG
#include <boost/log/sinks/syslog_backend.hpp>
#endif
BOOST_LOG_ATTRIBUTE_KEYWORD (severity, "Severity", nano::severity_level)
boost::shared_ptr<boost::log::sinks::synchronous_sink<boost::log::sinks::text_file_backend>> 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_level, severity_tag> ("Severity") << boost::log::expressions::smessage;
auto format_with_timestamp = boost::log::expressions::stream << "[" << boost::log::expressions::attr<boost::posix_time::ptime> ("TimeStamp") << "]: " << boost::log::expressions::attr<severity_level, severity_tag> ("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::sinks::synchronous_sink<boost::log::sinks::simple_event_log_backend>> (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<nano::severity_level> 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::sinks::synchronous_sink<boost::log::sinks::syslog_backend>> (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<nano::severity_level> 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);
}
}

4
nano/node/logging.hpp
View file

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

2
nano/slow_test/node.cpp
View file

@ -6,6 +6,8 @@
#include <thread>
using namespace std::chrono_literals;
TEST (system, generate_mass_activity)
{
nano::system system (24000, 1);