diff --git a/src/init.cpp b/src/init.cpp --- a/src/init.cpp +++ b/src/init.cpp @@ -1410,11 +1410,6 @@ 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 = @@ -1894,11 +1889,11 @@ // debug.log printing. logger.ShrinkDebugFile(); } + } - if (!logger.OpenDebugLog()) { - return InitError(strprintf("Could not open debug log file %s", - logger.m_file_path.string())); - } + if (!logger.StartLogging()) { + return InitError(strprintf("Could not open debug log file %s", + logger.m_file_path.string())); } if (!logger.m_log_timestamps) { diff --git a/src/logging.h b/src/logging.h --- a/src/logging.h +++ b/src/logging.h @@ -59,9 +59,15 @@ class Logger { private: + // Can not use Mutex from sync.h because in debug mode it would cause a + // deadlock when a potential deadlock was detected + mutable std::mutex m_cs; + // GUARDED_BY(m_cs) FILE *m_fileout = nullptr; - std::mutex m_file_mutex; + // GUARDED_BY(m_cs) std::list m_msgs_before_open; + //! Buffer messages before logging can be started. GUARDED_BY(m_cs) + bool m_buffering{true}; /** * m_started_new_line is a state variable that will suppress printing of the @@ -93,9 +99,14 @@ 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 { + std::lock_guard scoped_lock(m_cs); + return m_buffering || m_print_to_console || m_print_to_file; + } + + /** Start logging (and flush all buffered messages) */ + bool StartLogging(); - bool OpenDebugLog(); void ShrinkDebugFile(); uint32_t GetCategoryMask() const { return m_categories.load(); } diff --git a/src/logging.cpp b/src/logging.cpp --- a/src/logging.cpp +++ b/src/logging.cpp @@ -38,24 +38,44 @@ return fwrite(str.data(), 1, str.size(), fp); } -bool BCLog::Logger::OpenDebugLog() { - std::lock_guard scoped_lock(m_file_mutex); +bool BCLog::Logger::StartLogging() { + std::lock_guard scoped_lock(m_cs); + 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; + } + + // Unbuffered. + setbuf(m_fileout, nullptr); + + // Add newlines to the logfile to distinguish this execution from the + // last one. + FileWriteStr("\n\n\n\n\n", m_fileout); } - // Unbuffered. - setbuf(m_fileout, nullptr); // 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; } @@ -173,6 +193,7 @@ } void BCLog::Logger::LogPrintStr(const std::string &str) { + std::lock_guard scoped_lock(m_cs); std::string str_prefixed = str; if (m_log_threadnames && m_started_new_line) { @@ -183,31 +204,32 @@ 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) { - // unbuffered. - setbuf(m_fileout, nullptr); - 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) { + // unbuffered. + setbuf(m_fileout, nullptr); + fclose(m_fileout); + m_fileout = new_fileout; } - FileWriteStr(str_prefixed, m_fileout); } + FileWriteStr(str_prefixed, m_fileout); } } diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -42,9 +42,16 @@ with open(inc_conf_file_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