From a4e6c45238c8afaefe9f1e8e14397cede7acf3f9 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 20 Jan 2020 10:35:30 -0700 Subject: [PATCH] util: relog configuration arguments when debug.log rotates --- src/init/common.cpp | 6 +++- src/logging.cpp | 43 ++++++++++++++++-------- src/logging.h | 23 ++++++++++++- src/test/getarg_tests.cpp | 68 ++++++++++++++++++++++++++++++++++++++ src/test/logging_tests.cpp | 31 ++++++++--------- src/util/system.cpp | 5 ++- 6 files changed, 144 insertions(+), 32 deletions(-) diff --git a/src/init/common.cpp b/src/init/common.cpp index a0cdf44f474b1..8dcd161e70719 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -124,6 +124,10 @@ void LogPackageVersion() #else version_string += " (release build)"; #endif - LogPrintf(PACKAGE_NAME " version %s\n", version_string); + std::string str{strprintf("%s version %s", PACKAGE_NAME, version_string)}; + LogPrintf("%s\n", str); + + // Useful to always have in the debug.log file (even after log rotation). + LogInstance().AddRelogMessage(str); } } // namespace init diff --git a/src/logging.cpp b/src/logging.cpp index 1e2c1d5a77cb0..75dfd8e2ec5ba 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -287,7 +287,7 @@ std::vector BCLog::Logger::LogCategoriesList() const return ret; } -std::string BCLog::Logger::LogTimestampStr(const std::string& str) +std::string BCLog::Logger::LogTimestampStr(const std::string& str) const { std::string strStamped; @@ -368,9 +368,35 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] "); } + std::string str_console; + if (m_print_to_console) { + str_console = LogTimestampStr(str_prefixed); + } + + if (!m_buffering && m_print_to_file) { + assert(m_fileout != nullptr); + + // reopen the log file, if requested + if (m_reopen_file) { + m_reopen_file = false; + FILE* new_fileout = fsbridge::fopen(m_file_path, "a"); + if (new_fileout) { + setbuf(new_fileout, nullptr); // unbuffered + fclose(m_fileout); + m_fileout = new_fileout; + + // Re-log important messages to the new file so they're not lost. + m_started_new_line = true; // prepend timestamp to these messages + FileWriteStr(LogTimestampStr("*** reopen log file ***\n"), m_fileout); + for (const std::string& msg : m_msgs_relog) { + FileWriteStr(LogTimestampStr(msg) + '\n', m_fileout); + } + } + } + } str_prefixed = LogTimestampStr(str_prefixed); - m_started_new_line = !str.empty() && str[str.size()-1] == '\n'; + m_started_new_line = !str.empty() && str[str.size() - 1] == '\n'; if (m_buffering) { // buffer if we haven't started logging yet @@ -380,7 +406,7 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi if (m_print_to_console) { // print to console - fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout); + fwrite(str_console.data(), 1, str_console.size(), stdout); fflush(stdout); } for (const auto& cb : m_print_callbacks) { @@ -388,17 +414,6 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi } if (m_print_to_file) { assert(m_fileout != nullptr); - - // reopen the log file, if requested - if (m_reopen_file) { - m_reopen_file = false; - FILE* new_fileout = fsbridge::fopen(m_file_path, "a"); - if (new_fileout) { - setbuf(new_fileout, nullptr); // unbuffered - fclose(m_fileout); - m_fileout = new_fileout; - } - } FileWriteStr(str_prefixed, m_fileout); } } diff --git a/src/logging.h b/src/logging.h index 50869ad89a9b7..f7f5872b63584 100644 --- a/src/logging.h +++ b/src/logging.h @@ -84,6 +84,13 @@ namespace BCLog { std::list m_msgs_before_open GUARDED_BY(m_cs); bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started. + /** + * Some logged messages are important enough that they should be + * re-logged to the new debug.log file when it rotates, so that they + * are always visible near the start of the current debug.log file. + */ + std::list m_msgs_relog; + /** * m_started_new_line is a state variable that will suppress printing of * the timestamp when multiple calls are made that don't end in a @@ -94,7 +101,7 @@ namespace BCLog { /** Log categories bitfield. */ std::atomic m_categories{0}; - std::string LogTimestampStr(const std::string& str); + std::string LogTimestampStr(const std::string& str) const; /** Slots that connect to the print signal */ std::list> m_print_callbacks GUARDED_BY(m_cs) {}; @@ -160,6 +167,20 @@ namespace BCLog { }; bool DefaultShrinkDebugFile() const; + + /** (Re)log important string to debug.log later, each time it rotates */ + void AddRelogMessage(const std::string& str) + { + if (m_print_to_file) { + m_msgs_relog.push_back(str); + } + } + + /** Only for testing */ + void DeleteRelogMessages() + { + m_msgs_relog.clear(); + } }; } // namespace BCLog diff --git a/src/test/getarg_tests.cpp b/src/test/getarg_tests.cpp index 70dd137e2263f..954e3d7e1b5d5 100644 --- a/src/test/getarg_tests.cpp +++ b/src/test/getarg_tests.cpp @@ -442,6 +442,7 @@ BOOST_AUTO_TEST_CASE(logargs) local_args.LogArgs(); LogInstance().DeleteCallback(print_connection); + LogInstance().DeleteRelogMessages(); // Check that what should appear does, and what shouldn't doesn't. BOOST_CHECK(str.find("Command-line arg: okaylog-bool=\"\"") != std::string::npos); BOOST_CHECK(str.find("Command-line arg: okaylog-negbool=false") != std::string::npos); @@ -450,4 +451,71 @@ BOOST_AUTO_TEST_CASE(logargs) BOOST_CHECK(str.find("private") == std::string::npos); } +static void relogargscheck() +{ + // Open and read debug.log. This test can't use PushBackCallback() like the + // logargs test above because, by design, log file rotation doesn't cause + // the relogged messages to be sent to that interface, only to the file. + FILE* file = fsbridge::fopen(LogInstance().m_file_path, "rb"); + fseek(file, 0, SEEK_END); + std::vector vch(ftell(file), 0); + fseek(file, 0, SEEK_SET); + size_t nbytes = fread(vch.data(), 1, vch.size(), file); + fclose(file); + + assert(nbytes == vch.size()); + + // Check that what should appear does, and what shouldn't doesn't. + std::string str(vch.begin(), vch.end()); + BOOST_CHECK(str.find("test relogargs") != std::string::npos); + BOOST_CHECK(str.find("Bitcoin Core version") != std::string::npos); + BOOST_CHECK(str.find("Command-line arg: okaylog-bool=\"\"") != std::string::npos); + BOOST_CHECK(str.find("Command-line arg: okaylog-negbool=false") != std::string::npos); + BOOST_CHECK(str.find("Command-line arg: okaylog=\"public\"") != std::string::npos); + BOOST_CHECK(str.find("dontlog=****") != std::string::npos); + BOOST_CHECK(str.find("private") == std::string::npos); +} + +BOOST_AUTO_TEST_CASE(relogargs) +{ + ArgsManager local_args; + + const auto okaylog_bool = std::make_pair("-okaylog-bool", ArgsManager::ALLOW_ANY); + const auto okaylog_negbool = std::make_pair("-okaylog-negbool", ArgsManager::ALLOW_ANY); + const auto okaylog = std::make_pair("-okaylog", ArgsManager::ALLOW_ANY); + const auto dontlog = std::make_pair("-dontlog", ArgsManager::ALLOW_ANY | ArgsManager::SENSITIVE); + SetupArgs(local_args, {okaylog_bool, okaylog_negbool, okaylog, dontlog}); + ResetArgs(local_args, "-okaylog-bool -nookaylog-negbool -okaylog=public -dontlog=private"); + + // Log the arguments to debug.log. + local_args.LogArgs(); + + // This should also appear in the log. + LogPrintf("test relogargs\n"); + + // Verify that the arguments were logged. + relogargscheck(); + + // Simulate log rotation. +#ifdef WIN32 + // Windows doesn't allow an open file to be renamed, so close and reopen (below). + LogInstance().DisconnectTestLogger(); +#endif + fs::path newname = LogInstance().m_file_path + ".rename"; + fs::rename(LogInstance().m_file_path, newname); +#ifdef WIN32 + LogInstance().StartLogging(); +#endif + + // Simulate SIGHUP (on a real system, signal causes HandleSIGHUP() to run). + LogInstance().m_reopen_file = true; + + // The first log message after signal causes the arguments to be relogged. + LogPrintf("test relogargs\n"); + + // Verify that the arguments were (re)logged. + relogargscheck(); + LogInstance().DeleteRelogMessages(); +} + BOOST_AUTO_TEST_SUITE_END() diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 5a5e3b3f1f0ef..9328fefa66b6a 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -52,6 +52,19 @@ struct LogSetup : public BasicTestingSetup { LogInstance().m_log_threadnames = prev_log_threadnames; LogInstance().m_log_sourcelocations = prev_log_sourcelocations; } + + std::vector GetLogLines() const + { + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + // The log file get "reopened", so ignore some extra lines. + if (log.find("reopen log file") != std::string::npos) continue; + if (log.find("version") != std::string::npos) continue; + log_lines.push_back(log); + } + return log_lines; + } }; BOOST_AUTO_TEST_CASE(logging_timer) @@ -78,11 +91,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup) LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s", "bar2\n"); LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s", "bar3\n"); LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s", "bar4\n"); - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{GetLogLines()}; std::vector expected = { "[src1:1] [fn1] [net:debug] foo1: bar1", "[src2:2] [fn2] [net] foo2: bar2", @@ -104,11 +113,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup) LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9"); LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10"); LogPrintfCategory(BCLog::VALIDATION, "foo11: %s\n", "bar11"); - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{GetLogLines()}; std::vector expected = { "foo5: bar5", "[net] foo6: bar6", @@ -145,11 +150,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup) expected.push_back(expected_log); } - std::ifstream file{tmp_log_path}; - std::vector log_lines; - for (std::string log; std::getline(file, log);) { - log_lines.push_back(log); - } + std::vector log_lines{GetLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } diff --git a/src/util/system.cpp b/src/util/system.cpp index ce45fb2ed4d95..3cfa8cc96684b 100644 --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -1115,7 +1115,10 @@ void ArgsManager::logArgsPrefix( std::optional flags = GetArgFlags('-' + arg.first); if (flags) { std::string value_str = (*flags & SENSITIVE) ? "****" : value.write(); - LogPrintf("%s %s%s=%s\n", prefix, section_str, arg.first, value_str); + std::string str{strprintf("%s %s%s=%s", prefix, section_str, arg.first, value_str)}; + LogPrintf("%s\n", str); + // Useful to always have in the current debug.log file. + LogInstance().AddRelogMessage(str); } } }