From f55f4fcf05a53fdf618b4c69ddcf4c43b14e84c2 Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Wed, 11 Apr 2018 10:03:21 -0700 Subject: util: Establish global logger object. The object encapsulates logging configuration, and in a later commit, set up routines will also be moved into the class. --- src/logging.cpp | 37 ++++++++++++++++++++----------------- 1 file changed, 20 insertions(+), 17 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index e48158232..de222d946 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -12,13 +12,22 @@ const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; -bool fPrintToConsole = false; -bool fPrintToDebugLog = true; +/** + * NOTE: the logger instances is leaked on exit. This is ugly, but will be + * cleaned up by the OS/libc. Defining a logger as a global object doesn't work + * since the order of destruction of static/global objects is undefined. + * Consider if the logger gets destroyed, and then some later destructor calls + * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to + * access the logger. When the shutdown sequence is fully audited and tested, + * explicit destruction of these objects can be implemented by changing this + * from a raw pointer to a std::unique_ptr. + * + * This method of initialization was originally introduced in + * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c. + */ +BCLog::Logger* const g_logger = new BCLog::Logger(); -bool fLogTimestamps = DEFAULT_LOGTIMESTAMPS; -bool fLogTimeMicros = DEFAULT_LOGTIMEMICROS; bool fLogIPs = DEFAULT_LOGIPS; -std::atomic fReopenDebugLog(false); /** Log categories bitfield. */ std::atomic logCategories(0); @@ -174,19 +183,14 @@ std::vector ListActiveLogCategories() return ret; } -/** - * fStartedNewLine is a state variable held by the calling context that will - * suppress printing of the timestamp when multiple calls are made that don't - * end in a newline. Initialize it to true, and hold it, in the calling context. - */ -static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fStartedNewLine) +std::string BCLog::Logger::LogTimestampStr(const std::string &str) { std::string strStamped; if (!fLogTimestamps) return str; - if (*fStartedNewLine) { + if (fStartedNewLine) { int64_t nTimeMicros = GetTimeMicros(); strStamped = FormatISO8601DateTime(nTimeMicros/1000000); if (fLogTimeMicros) { @@ -202,19 +206,18 @@ static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fSt strStamped = str; if (!str.empty() && str[str.size()-1] == '\n') - *fStartedNewLine = true; + fStartedNewLine = true; else - *fStartedNewLine = false; + fStartedNewLine = false; return strStamped; } -int LogPrintStr(const std::string &str) +int BCLog::Logger::LogPrintStr(const std::string &str) { int ret = 0; // Returns total number of characters written - static std::atomic_bool fStartedNewLine(true); - std::string strTimestamped = LogTimestampStr(str, &fStartedNewLine); + std::string strTimestamped = LogTimestampStr(str); if (fPrintToConsole) { // print to console -- cgit v1.2.3 From 6a6d764ca5616e5d1f1848b0010613c49bd38e61 Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Wed, 11 Apr 2018 11:12:51 -0700 Subject: util: Move debug file management functions into Logger. --- src/logging.cpp | 59 +++++++++------------------------------------------------ 1 file changed, 9 insertions(+), 50 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index de222d946..ed225a6a6 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -7,9 +7,6 @@ #include #include -#include -#include - const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; /** @@ -31,57 +28,23 @@ bool fLogIPs = DEFAULT_LOGIPS; /** Log categories bitfield. */ std::atomic logCategories(0); -/** - * LogPrintf() has been broken a couple of times now - * by well-meaning people adding mutexes in the most straightforward way. - * It breaks because it may be called by global destructors during shutdown. - * Since the order of destruction of static/global objects is undefined, - * defining a mutex as a global object doesn't work (the mutex gets - * destroyed, and then some later destructor calls OutputDebugStringF, - * maybe indirectly, and you get a core dump at shutdown trying to lock - * the mutex). - */ - -static std::once_flag debugPrintInitFlag; - -/** - * We use std::call_once() to make sure mutexDebugLog and - * vMsgsBeforeOpenLog are initialized in a thread-safe manner. - * - * NOTE: fileout, mutexDebugLog and sometimes vMsgsBeforeOpenLog - * are leaked on exit. This is ugly, but will be cleaned up by - * the OS/libc. When the shutdown sequence is fully audited and - * tested, explicit destruction of these objects can be implemented. - */ -static FILE* fileout = nullptr; -static std::mutex* mutexDebugLog = nullptr; -static std::list* vMsgsBeforeOpenLog; static int FileWriteStr(const std::string &str, FILE *fp) { return fwrite(str.data(), 1, str.size(), fp); } -static void DebugPrintInit() -{ - assert(mutexDebugLog == nullptr); - mutexDebugLog = new std::mutex(); - vMsgsBeforeOpenLog = new std::list; -} - -fs::path GetDebugLogPath() +fs::path BCLog::Logger::GetDebugLogPath() const { fs::path logfile(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE)); return AbsPathForConfigVal(logfile); } -bool OpenDebugLog() +bool BCLog::Logger::OpenDebugLog() { - std::call_once(debugPrintInitFlag, &DebugPrintInit); - std::lock_guard scoped_lock(*mutexDebugLog); + std::lock_guard scoped_lock(mutexDebugLog); assert(fileout == nullptr); - assert(vMsgsBeforeOpenLog); fs::path pathDebug = GetDebugLogPath(); fileout = fsbridge::fopen(pathDebug, "a"); @@ -91,13 +54,11 @@ bool OpenDebugLog() setbuf(fileout, nullptr); // unbuffered // dump buffered messages from before we opened the log - while (!vMsgsBeforeOpenLog->empty()) { - FileWriteStr(vMsgsBeforeOpenLog->front(), fileout); - vMsgsBeforeOpenLog->pop_front(); + while (!vMsgsBeforeOpenLog.empty()) { + FileWriteStr(vMsgsBeforeOpenLog.front(), fileout); + vMsgsBeforeOpenLog.pop_front(); } - delete vMsgsBeforeOpenLog; - vMsgsBeforeOpenLog = nullptr; return true; } @@ -225,14 +186,12 @@ int BCLog::Logger::LogPrintStr(const std::string &str) fflush(stdout); } if (fPrintToDebugLog) { - std::call_once(debugPrintInitFlag, &DebugPrintInit); - std::lock_guard scoped_lock(*mutexDebugLog); + std::lock_guard scoped_lock(mutexDebugLog); // buffer if we haven't opened the log yet if (fileout == nullptr) { - assert(vMsgsBeforeOpenLog); ret = strTimestamped.length(); - vMsgsBeforeOpenLog->push_back(strTimestamped); + vMsgsBeforeOpenLog.push_back(strTimestamped); } else { @@ -250,7 +209,7 @@ int BCLog::Logger::LogPrintStr(const std::string &str) return ret; } -void ShrinkDebugFile() +void BCLog::Logger::ShrinkDebugFile() { // Amount of debug.log to save at end when shrinking (must fit in memory) constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000; -- cgit v1.2.3 From 3316a9ebb66171937efddb213daed64fe51c4082 Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Wed, 11 Apr 2018 13:02:01 -0700 Subject: util: Encapsulate logCategories within BCLog::Logger. --- src/logging.cpp | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index ed225a6a6..7604c0fd9 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -26,9 +26,6 @@ BCLog::Logger* const g_logger = new BCLog::Logger(); bool fLogIPs = DEFAULT_LOGIPS; -/** Log categories bitfield. */ -std::atomic logCategories(0); - static int FileWriteStr(const std::string &str, FILE *fp) { return fwrite(str.data(), 1, str.size(), fp); @@ -62,6 +59,26 @@ bool BCLog::Logger::OpenDebugLog() return true; } +void BCLog::Logger::EnableCategory(BCLog::LogFlags flag) +{ + logCategories |= flag; +} + +void BCLog::Logger::DisableCategory(BCLog::LogFlags flag) +{ + logCategories &= ~flag; +} + +bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const +{ + return (logCategories.load(std::memory_order_relaxed) & category) != 0; +} + +bool BCLog::Logger::DefaultShrinkDebugFile() const +{ + return logCategories == BCLog::NONE; +} + struct CLogCategoryDesc { uint32_t flag; -- cgit v1.2.3 From 1eac317f25b905e97e311130ab19c3b0d257fc04 Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Wed, 11 Apr 2018 14:06:35 -0700 Subject: util: Refactor GetLogCategory. Changing parameter types from pointers to references and uint32_t to BCLog::LogFlags simplies calling code. --- src/logging.cpp | 51 ++++++++++++++++++++++++++++++++------------------- 1 file changed, 32 insertions(+), 19 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index 7604c0fd9..dc1ed0afb 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -5,7 +5,6 @@ #include #include -#include const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; @@ -64,11 +63,27 @@ void BCLog::Logger::EnableCategory(BCLog::LogFlags flag) logCategories |= flag; } +bool BCLog::Logger::EnableCategory(const std::string& str) +{ + BCLog::LogFlags flag; + if (!GetLogCategory(flag, str)) return false; + EnableCategory(flag); + return true; +} + void BCLog::Logger::DisableCategory(BCLog::LogFlags flag) { logCategories &= ~flag; } +bool BCLog::Logger::DisableCategory(const std::string& str) +{ + BCLog::LogFlags flag; + if (!GetLogCategory(flag, str)) return false; + DisableCategory(flag); + return true; +} + bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const { return (logCategories.load(std::memory_order_relaxed) & category) != 0; @@ -81,7 +96,7 @@ bool BCLog::Logger::DefaultShrinkDebugFile() const struct CLogCategoryDesc { - uint32_t flag; + BCLog::LogFlags flag; std::string category; }; @@ -114,19 +129,17 @@ const CLogCategoryDesc LogCategories[] = {BCLog::ALL, "all"}, }; -bool GetLogCategory(uint32_t *f, const std::string *str) +bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str) { - if (f && str) { - if (*str == "") { - *f = BCLog::ALL; + if (str == "") { + flag = BCLog::ALL; + return true; + } + for (const CLogCategoryDesc& category_desc : LogCategories) { + if (category_desc.category == str) { + flag = category_desc.flag; return true; } - for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { - if (LogCategories[i].category == *str) { - *f = LogCategories[i].flag; - return true; - } - } } return false; } @@ -135,11 +148,11 @@ std::string ListLogCategories() { std::string ret; int outcount = 0; - for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { + for (const CLogCategoryDesc& category_desc : LogCategories) { // Omit the special cases. - if (LogCategories[i].flag != BCLog::NONE && LogCategories[i].flag != BCLog::ALL) { + if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) { if (outcount != 0) ret += ", "; - ret += LogCategories[i].category; + ret += category_desc.category; outcount++; } } @@ -149,12 +162,12 @@ std::string ListLogCategories() std::vector ListActiveLogCategories() { std::vector ret; - for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { + for (const CLogCategoryDesc& category_desc : LogCategories) { // Omit the special cases. - if (LogCategories[i].flag != BCLog::NONE && LogCategories[i].flag != BCLog::ALL) { + if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) { CLogCategoryActive catActive; - catActive.category = LogCategories[i].category; - catActive.active = LogAcceptCategory(LogCategories[i].flag); + catActive.category = category_desc.category; + catActive.active = LogAcceptCategory(category_desc.flag); ret.push_back(catActive); } } -- cgit v1.2.3 From 8e7b961388920144993d0bd56d93f89e5c60fbff Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Fri, 20 Apr 2018 00:42:32 -0700 Subject: scripted-diff: Rename BCLog::Logger member variables. -BEGIN VERIFY SCRIPT- sed -i "s/fileout/m_fileout/" src/logging.h src/logging.cpp sed -i "s/mutexDebugLog/m_file_mutex/" src/logging.h src/logging.cpp sed -i "s/vMsgsBeforeOpenLog/m_msgs_before_open/" src/logging.h src/logging.cpp sed -i "s/logCategories/m_categories/" src/logging.h src/logging.cpp sed -i "s/fPrintToConsole/m_print_to_console/" src/logging.h src/logging.cpp src/init.cpp sed -i "s/fPrintToDebugLog/m_print_to_file/" src/logging.h src/logging.cpp src/init.cpp src/test/test_bitcoin.cpp src/bench/bench_bitcoin.cpp sed -i "s/fLogTimestamps/m_log_timestamps/" src/logging.h src/logging.cpp src/init.cpp sed -i "s/fLogTimeMicros/m_log_time_micros/" src/logging.h src/logging.cpp src/init.cpp sed -i "s/fReopenDebugLog/m_reopen_file/" src/logging.h src/logging.cpp src/init.cpp sed -i "s/fStartedNewLine/m_started_new_line/" src/logging.h src/logging.cpp -END VERIFY SCRIPT- --- src/logging.cpp | 54 +++++++++++++++++++++++++++--------------------------- 1 file changed, 27 insertions(+), 27 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index dc1ed0afb..b7c682c94 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -38,21 +38,21 @@ fs::path BCLog::Logger::GetDebugLogPath() const bool BCLog::Logger::OpenDebugLog() { - std::lock_guard scoped_lock(mutexDebugLog); + std::lock_guard scoped_lock(m_file_mutex); - assert(fileout == nullptr); + assert(m_fileout == nullptr); fs::path pathDebug = GetDebugLogPath(); - fileout = fsbridge::fopen(pathDebug, "a"); - if (!fileout) { + m_fileout = fsbridge::fopen(pathDebug, "a"); + if (!m_fileout) { return false; } - setbuf(fileout, nullptr); // unbuffered + setbuf(m_fileout, nullptr); // unbuffered // dump buffered messages from before we opened the log - while (!vMsgsBeforeOpenLog.empty()) { - FileWriteStr(vMsgsBeforeOpenLog.front(), fileout); - vMsgsBeforeOpenLog.pop_front(); + while (!m_msgs_before_open.empty()) { + FileWriteStr(m_msgs_before_open.front(), m_fileout); + m_msgs_before_open.pop_front(); } return true; @@ -60,7 +60,7 @@ bool BCLog::Logger::OpenDebugLog() void BCLog::Logger::EnableCategory(BCLog::LogFlags flag) { - logCategories |= flag; + m_categories |= flag; } bool BCLog::Logger::EnableCategory(const std::string& str) @@ -73,7 +73,7 @@ bool BCLog::Logger::EnableCategory(const std::string& str) void BCLog::Logger::DisableCategory(BCLog::LogFlags flag) { - logCategories &= ~flag; + m_categories &= ~flag; } bool BCLog::Logger::DisableCategory(const std::string& str) @@ -86,12 +86,12 @@ bool BCLog::Logger::DisableCategory(const std::string& str) bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const { - return (logCategories.load(std::memory_order_relaxed) & category) != 0; + return (m_categories.load(std::memory_order_relaxed) & category) != 0; } bool BCLog::Logger::DefaultShrinkDebugFile() const { - return logCategories == BCLog::NONE; + return m_categories == BCLog::NONE; } struct CLogCategoryDesc @@ -178,13 +178,13 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str) { std::string strStamped; - if (!fLogTimestamps) + if (!m_log_timestamps) return str; - if (fStartedNewLine) { + if (m_started_new_line) { int64_t nTimeMicros = GetTimeMicros(); strStamped = FormatISO8601DateTime(nTimeMicros/1000000); - if (fLogTimeMicros) { + if (m_log_time_micros) { strStamped.pop_back(); strStamped += strprintf(".%06dZ", nTimeMicros%1000000); } @@ -197,9 +197,9 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str) strStamped = str; if (!str.empty() && str[str.size()-1] == '\n') - fStartedNewLine = true; + m_started_new_line = true; else - fStartedNewLine = false; + m_started_new_line = false; return strStamped; } @@ -210,30 +210,30 @@ int BCLog::Logger::LogPrintStr(const std::string &str) std::string strTimestamped = LogTimestampStr(str); - if (fPrintToConsole) { + if (m_print_to_console) { // print to console ret = fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout); fflush(stdout); } - if (fPrintToDebugLog) { - std::lock_guard scoped_lock(mutexDebugLog); + if (m_print_to_file) { + std::lock_guard scoped_lock(m_file_mutex); // buffer if we haven't opened the log yet - if (fileout == nullptr) { + if (m_fileout == nullptr) { ret = strTimestamped.length(); - vMsgsBeforeOpenLog.push_back(strTimestamped); + m_msgs_before_open.push_back(strTimestamped); } else { // reopen the log file, if requested - if (fReopenDebugLog) { - fReopenDebugLog = false; + if (m_reopen_file) { + m_reopen_file = false; fs::path pathDebug = GetDebugLogPath(); - if (fsbridge::freopen(pathDebug,"a",fileout) != nullptr) - setbuf(fileout, nullptr); // unbuffered + if (fsbridge::freopen(pathDebug,"a",m_fileout) != nullptr) + setbuf(m_fileout, nullptr); // unbuffered } - ret = FileWriteStr(strTimestamped, fileout); + ret = FileWriteStr(strTimestamped, m_fileout); } } return ret; -- cgit v1.2.3 From 8c2d695c4a45bdd9378c7970b0fcba6e1efc01f9 Mon Sep 17 00:00:00 2001 From: Jim Posen Date: Fri, 20 Apr 2018 01:11:44 -0700 Subject: util: Store debug log file path in BCLog::Logger member. This breaks the cyclic between logging and util. --- src/logging.cpp | 25 ++++++++++--------------- 1 file changed, 10 insertions(+), 15 deletions(-) (limited to 'src/logging.cpp') diff --git a/src/logging.cpp b/src/logging.cpp index b7c682c94..10a3b1895 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -4,7 +4,7 @@ // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include -#include +#include const char * const DEFAULT_DEBUGLOGFILE = "debug.log"; @@ -30,20 +30,14 @@ static int FileWriteStr(const std::string &str, FILE *fp) return fwrite(str.data(), 1, str.size(), fp); } -fs::path BCLog::Logger::GetDebugLogPath() const -{ - fs::path logfile(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE)); - return AbsPathForConfigVal(logfile); -} - bool BCLog::Logger::OpenDebugLog() { std::lock_guard scoped_lock(m_file_mutex); assert(m_fileout == nullptr); - fs::path pathDebug = GetDebugLogPath(); + assert(!m_file_path.empty()); - m_fileout = fsbridge::fopen(pathDebug, "a"); + m_fileout = fsbridge::fopen(m_file_path, "a"); if (!m_fileout) { return false; } @@ -228,8 +222,7 @@ int BCLog::Logger::LogPrintStr(const std::string &str) // reopen the log file, if requested if (m_reopen_file) { m_reopen_file = false; - fs::path pathDebug = GetDebugLogPath(); - if (fsbridge::freopen(pathDebug,"a",m_fileout) != nullptr) + if (fsbridge::freopen(m_file_path,"a",m_fileout) != nullptr) setbuf(m_fileout, nullptr); // unbuffered } @@ -243,14 +236,16 @@ void BCLog::Logger::ShrinkDebugFile() { // Amount of debug.log to save at end when shrinking (must fit in memory) constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000; + + assert(!m_file_path.empty()); + // Scroll debug.log if it's getting too big - fs::path pathLog = GetDebugLogPath(); - FILE* file = fsbridge::fopen(pathLog, "r"); + FILE* file = fsbridge::fopen(m_file_path, "r"); // Special files (e.g. device nodes) may not have a size. size_t log_size = 0; try { - log_size = fs::file_size(pathLog); + log_size = fs::file_size(m_file_path); } catch (boost::filesystem::filesystem_error &) {} // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE @@ -263,7 +258,7 @@ void BCLog::Logger::ShrinkDebugFile() int nBytes = fread(vch.data(), 1, vch.size(), file); fclose(file); - file = fsbridge::fopen(pathLog, "w"); + file = fsbridge::fopen(m_file_path, "w"); if (file) { fwrite(vch.data(), 1, nBytes, file); -- cgit v1.2.3