From 0b282f9b00da08734e2381477aad32d64b933745 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Thu, 3 May 2018 11:09:28 +1000 Subject: [PATCH] Log early messages with -printtoconsole This ensures log messages prior to StartLogging() are replayed to the console as well as to the debug log file. --- src/init.cpp | 6 --- src/logging.cpp | 63 ++++++++++++++++---------- src/logging.h | 5 +- test/functional/feature_config_args.py | 7 +++ 4 files changed, 49 insertions(+), 32 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index fdfde689f9b..9245d5e593e 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -855,12 +855,6 @@ void InitLogging() { LogInstance().m_print_to_file = !gArgs.IsArgNegated("-debuglogfile"); LogInstance().m_file_path = AbsPathForConfigVal(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE)); - - // Add newlines to the logfile to distinguish this execution from the last - // one; called before console logging is set up, so this is only sent to - // debug.log. - LogPrintf("\n\n\n\n\n"); - LogInstance().m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false)); LogInstance().m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS); LogInstance().m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS); diff --git a/src/logging.cpp b/src/logging.cpp index f9d9d9c56be..268614065ac 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -42,22 +42,35 @@ static int FileWriteStr(const std::string &str, FILE *fp) bool BCLog::Logger::StartLogging() { std::lock_guard scoped_lock(m_file_mutex); - if (!m_print_to_file) return true; + assert(m_buffering); assert(m_fileout == nullptr); - assert(!m_file_path.empty()); - m_fileout = fsbridge::fopen(m_file_path, "a"); - if (!m_fileout) { - return false; + if (m_print_to_file) { + assert(!m_file_path.empty()); + m_fileout = fsbridge::fopen(m_file_path, "a"); + if (!m_fileout) { + return false; + } + + setbuf(m_fileout, nullptr); // unbuffered + + // Add newlines to the logfile to distinguish this execution from the + // last one. + FileWriteStr("\n\n\n\n\n", m_fileout); } - setbuf(m_fileout, nullptr); // unbuffered // dump buffered messages from before we opened the log + m_buffering = false; while (!m_msgs_before_open.empty()) { - FileWriteStr(m_msgs_before_open.front(), m_fileout); + const std::string& s = m_msgs_before_open.front(); + + if (m_print_to_file) FileWriteStr(s, m_fileout); + if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout); + m_msgs_before_open.pop_front(); } + if (m_print_to_console) fflush(stdout); return true; } @@ -205,6 +218,7 @@ std::string BCLog::Logger::LogTimestampStr(const std::string& str) void BCLog::Logger::LogPrintStr(const std::string &str) { + std::lock_guard scoped_lock(m_file_mutex); std::string str_prefixed = str; if (m_log_threadnames && m_started_new_line) { @@ -215,32 +229,31 @@ void BCLog::Logger::LogPrintStr(const std::string &str) m_started_new_line = !str.empty() && str[str.size()-1] == '\n'; + if (m_buffering) { + // buffer if we haven't started logging yet + m_msgs_before_open.push_back(str_prefixed); + return; + } + if (m_print_to_console) { // print to console fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout); fflush(stdout); } if (m_print_to_file) { - std::lock_guard scoped_lock(m_file_mutex); - - // buffer if we haven't opened the log yet - if (m_fileout == nullptr) { - m_msgs_before_open.push_back(str_prefixed); - } - else - { - // 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; - } + 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); } + FileWriteStr(str_prefixed, m_fileout); } } diff --git a/src/logging.h b/src/logging.h index 4fa9e0c8a47..f40a10bc4c1 100644 --- a/src/logging.h +++ b/src/logging.h @@ -63,6 +63,7 @@ namespace BCLog { FILE* m_fileout = nullptr; std::mutex m_file_mutex; std::list m_msgs_before_open; + bool m_buffering = true; //!< Buffer messages before logging can be started /** * m_started_new_line is a state variable that will suppress printing of @@ -91,9 +92,11 @@ namespace BCLog { void LogPrintStr(const std::string &str); /** Returns whether logs will be written to any output */ - bool Enabled() const { return m_print_to_console || m_print_to_file; } + bool Enabled() const { return m_buffering || m_print_to_console || m_print_to_file; } + /** Start logging (and flush all buffered messages) */ bool StartLogging(); + void ShrinkDebugFile(); uint32_t GetCategoryMask() const { return m_categories.load(); } diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index 2b93e3c24d7..074a8325942 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -61,9 +61,16 @@ class ConfArgsTest(BitcoinTestFramework): with open(inc_conf_file2_path, 'w', encoding='utf-8') as conf: conf.write('') # clear + def test_log_buffer(self): + with self.nodes[0].assert_debug_log(expected_msgs=['Warning: parsed potentially confusing double-negative -connect=0']): + self.start_node(0, extra_args=['-noconnect=0']) + self.stop_node(0) + def run_test(self): self.stop_node(0) + self.test_log_buffer() + self.test_config_file_parser() # Remove the -datadir argument so it doesn't override the config file