From 412987430c98e78ccda033ab1cf7a176a4c0b835 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Thu, 3 May 2018 10:14:01 +1000 Subject: Replace OpenDebugLog() with StartLogging() StartLogging() is used to mark the start of logging generically, whether using -printtoconsole or -debuglogfile. --- src/init.cpp | 4 ++-- src/logging.cpp | 3 ++- src/logging.h | 2 +- 3 files changed, 5 insertions(+), 4 deletions(-) (limited to 'src') diff --git a/src/init.cpp b/src/init.cpp index 2bb270647a..fdfde689f9 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1249,10 +1249,10 @@ bool AppInitMain(InitInterfaces& interfaces) // and because this needs to happen before any other debug.log printing LogInstance().ShrinkDebugFile(); } - if (!LogInstance().OpenDebugLog()) { + } + if (!LogInstance().StartLogging()) { return InitError(strprintf("Could not open debug log file %s", LogInstance().m_file_path.string())); - } } if (!LogInstance().m_log_timestamps) diff --git a/src/logging.cpp b/src/logging.cpp index 3eda4995db..f9d9d9c56b 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -39,9 +39,10 @@ static int FileWriteStr(const std::string &str, FILE *fp) return fwrite(str.data(), 1, str.size(), fp); } -bool BCLog::Logger::OpenDebugLog() +bool BCLog::Logger::StartLogging() { std::lock_guard scoped_lock(m_file_mutex); + if (!m_print_to_file) return true; assert(m_fileout == nullptr); assert(!m_file_path.empty()); diff --git a/src/logging.h b/src/logging.h index e399d4c307..4fa9e0c8a4 100644 --- a/src/logging.h +++ b/src/logging.h @@ -93,7 +93,7 @@ namespace BCLog { /** Returns whether logs will be written to any output */ bool Enabled() const { return m_print_to_console || m_print_to_file; } - bool OpenDebugLog(); + bool StartLogging(); void ShrinkDebugFile(); uint32_t GetCategoryMask() const { return m_categories.load(); } -- cgit v1.2.3 From 0b282f9b00da08734e2381477aad32d64b933745 Mon Sep 17 00:00:00 2001 From: Anthony Towns Date: Thu, 3 May 2018 11:09:28 +1000 Subject: 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 ++++- 3 files changed, 42 insertions(+), 32 deletions(-) (limited to 'src') diff --git a/src/init.cpp b/src/init.cpp index fdfde689f9..9245d5e593 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 f9d9d9c56b..268614065a 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 4fa9e0c8a4..f40a10bc4c 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(); } -- cgit v1.2.3 From faa2a47cd7bcdbd187035c76f8dbd0442f6818dc Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Tue, 28 May 2019 10:39:29 -0400 Subject: logging: Add threadsafety comments --- src/logging.cpp | 6 +++--- src/logging.h | 16 ++++++++++------ 2 files changed, 13 insertions(+), 9 deletions(-) (limited to 'src') diff --git a/src/logging.cpp b/src/logging.cpp index 268614065a..418a701179 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -41,7 +41,7 @@ static int FileWriteStr(const std::string &str, FILE *fp) bool BCLog::Logger::StartLogging() { - std::lock_guard scoped_lock(m_file_mutex); + std::lock_guard scoped_lock(m_cs); assert(m_buffering); assert(m_fileout == nullptr); @@ -216,9 +216,9 @@ std::string BCLog::Logger::LogTimestampStr(const std::string& str) return strStamped; } -void BCLog::Logger::LogPrintStr(const std::string &str) +void BCLog::Logger::LogPrintStr(const std::string& str) { - std::lock_guard scoped_lock(m_file_mutex); + std::lock_guard scoped_lock(m_cs); std::string str_prefixed = str; if (m_log_threadnames && m_started_new_line) { diff --git a/src/logging.h b/src/logging.h index f40a10bc4c..36b1a4045d 100644 --- a/src/logging.h +++ b/src/logging.h @@ -60,10 +60,10 @@ namespace BCLog { class Logger { private: - 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 + mutable std::mutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected + FILE* m_fileout = nullptr; // GUARDED_BY(m_cs) + std::list m_msgs_before_open; // GUARDED_BY(m_cs) + bool m_buffering{true}; //!< Buffer messages before logging can be started. GUARDED_BY(m_cs) /** * m_started_new_line is a state variable that will suppress printing of @@ -89,10 +89,14 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(const std::string &str); + void LogPrintStr(const std::string& str); /** Returns whether logs will be written to any output */ - bool Enabled() const { return m_buffering || 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(); -- cgit v1.2.3