From e5bf356db0154f4727abf28fc5162fface2f89d0 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Thu, 13 Aug 2020 11:50:04 +0100 Subject: [PATCH 1/2] Logging exception handler and fix for stable_log_filename on windows Although our logger has never thrown in normal conditions, it has been reported to when stressing the RPC in a RAM node, especially with a low rotation file size. This adds an exception handler that handles by simply prints to stderr. Also fixes an issue with the `stable_log_filename` config on Windows. The `node.log` file was being created with read-only permissions, so writing to the file after restarting the node would throw an exception. However, this can't be unit tested because the file gets the full permissions by default. The change to `nano::logging::release_file_sink ()` enables the added test. --- nano/core_test/logger.cpp | 32 ++++++++++++++++++++++++++++++++ nano/node/logging.cpp | 24 +++++++++++++++++++++++- 2 files changed, 55 insertions(+), 1 deletion(-) diff --git a/nano/core_test/logger.cpp b/nano/core_test/logger.cpp index 8a769e047d..18c6272bbf 100644 --- a/nano/core_test/logger.cpp +++ b/nano/core_test/logger.cpp @@ -121,3 +121,35 @@ TEST (logger, always_log) std::getline (ss, str, '\n'); ASSERT_STREQ (str.c_str (), output2); } + +TEST (logger, stable_filename) +{ + auto path (nano::unique_path ()); + nano::logging logging; + + // Releasing allows setting up logging again + logging.release_file_sink (); + + logging.stable_log_filename = true; + logging.init (path); + + nano::logger_mt logger (logging.min_time_between_log_output); + logger.always_log ("stable1"); + + auto log_file = path / "log" / "node.log"; + +#if BOOST_VERSION >= 107000 + EXPECT_TRUE (boost::filesystem::exists (log_file)); + // Try opening it again + logging.release_file_sink (); + logging.init (path); + logger.always_log ("stable2"); +#else + // When using Boost < 1.70 , behavior is reverted to not using the stable filename + EXPECT_FALSE (boost::filesystem::exists (log_file)); +#endif + + // Reset the logger + logging.release_file_sink (); + nano::logging ().init (path); +} \ No newline at end of file diff --git a/nano/node/logging.cpp b/nano/node/logging.cpp index 2fb2d284c0..571073aa70 100644 --- a/nano/node/logging.cpp +++ b/nano/node/logging.cpp @@ -6,6 +6,7 @@ #include #include +#include #include #include #include @@ -81,11 +82,12 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) if (stable_log_filename) { #if BOOST_VERSION >= 107000 + auto const file_name = path / "node.log"; // Logging to node.log and node_ instead of log_.log is deliberate. This way, // existing log monitoring scripts expecting the old logfile structure will fail immediately instead // of reading only rotated files with old entries. file_sink = boost::log::add_file_log (boost::log::keywords::target = path, - boost::log::keywords::file_name = path / "node.log", + boost::log::keywords::file_name = file_name, boost::log::keywords::target_file_name = path / "node_%Y-%m-%d_%H-%M-%S.%N.log", boost::log::keywords::open_mode = std::ios_base::out | std::ios_base::app, // append to node.log if it exists boost::log::keywords::enable_final_rotation = false, // for stable log filenames, don't rotate on destruction @@ -94,6 +96,15 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) boost::log::keywords::scan_method = boost::log::sinks::file::scan_method::scan_matching, boost::log::keywords::max_size = max_size, // max total size in bytes of all log files boost::log::keywords::format = format_with_timestamp); + + if (!boost::filesystem::exists (file_name)) + { + // Create temp stream to first create the file + std::ofstream stream (file_name.string ()); + + // Set permissions before opening otherwise Windows only has read permissions + nano::set_secure_perm_file (file_name); + } #else debug_assert (false); #endif @@ -108,6 +119,16 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) boost::log::keywords::max_size = max_size, boost::log::keywords::format = format_with_timestamp); } + + struct exception_handler + { + void operator() (std::exception const & e) const + { + std::cerr << "Logging exception: " << e.what () << std::endl; + } + }; + + boost::log::core::get ()->set_exception_handler (boost::log::make_exception_handler (exception_handler ())); } //clang-format on } @@ -118,6 +139,7 @@ void nano::logging::release_file_sink () { boost::log::core::get ()->remove_sink (nano::logging::file_sink); nano::logging::file_sink.reset (); + logging_already_added.clear (); } } From d4aee212034f689e2ce117d258454e00df89b940 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 14 Aug 2020 14:13:26 +0100 Subject: [PATCH 2/2] Set permissions for pre-existing log file as well, as Boost re-creates with read-only on rotation --- nano/node/logging.cpp | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/nano/node/logging.cpp b/nano/node/logging.cpp index 571073aa70..6115d0b249 100644 --- a/nano/node/logging.cpp +++ b/nano/node/logging.cpp @@ -101,10 +101,11 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) { // Create temp stream to first create the file std::ofstream stream (file_name.string ()); - - // Set permissions before opening otherwise Windows only has read permissions - nano::set_secure_perm_file (file_name); } + + // Set permissions before opening otherwise Windows only has read permissions + nano::set_secure_perm_file (file_name); + #else debug_assert (false); #endif