From fefd70b94345580768488923f4759ea70de681d1 Mon Sep 17 00:00:00 2001 From: Joseph Geumlek Date: Tue, 21 Jun 2022 22:06:20 -0700 Subject: [PATCH 1/2] Make logging more thread-safe --- es-core/src/Log.cpp | 50 ++++++++++++++++++++++++++++++++++++++++++++- es-core/src/Log.h | 19 ++++++++++------- 2 files changed, 61 insertions(+), 8 deletions(-) diff --git a/es-core/src/Log.cpp b/es-core/src/Log.cpp index 02b9468c4..b09e78049 100644 --- a/es-core/src/Log.cpp +++ b/es-core/src/Log.cpp @@ -9,8 +9,37 @@ #include "Log.h" #include "utils/StringUtil.h" +LogLevel Log::getReportingLevel() +{ + // Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; + return sReportingLevel; +} + +void Log::setReportingLevel(LogLevel level) +{ + // Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; + sReportingLevel = level; +} + +std::string Log::getLogPath() +{ + // No attempt is made to make this thread-safe. + // Currently getLogPath is public, and called in contexts with + // and without sLogMutex locked. + + // getHomePath() currently does not generate any Log messages. + return Utils::FileSystem::getHomePath() + "/.emulationstation/es_log.txt"; +} + void Log::init() { + // No attempt is made to make this thread-safe. + // It is unlikely to be called across multiple threads. + // Both removeFile and renameFile might generate log messages, + // so they might try to grab the lock. + Utils::FileSystem::removeFile(getLogPath() + ".bak"); // Rename the previous log file. Utils::FileSystem::renameFile(getLogPath(), getLogPath() + ".bak", true); @@ -19,6 +48,8 @@ void Log::init() void Log::open() { + // Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; #if defined(_WIN64) sFile.open(Utils::String::stringToWideString(getLogPath()).c_str()); #else @@ -28,6 +59,7 @@ void Log::open() std::ostringstream& Log::get(LogLevel level) { + // This function is not-static, lock is guarded by the Log() instance. time_t t {time(nullptr)}; struct tm tm; #if defined(_WIN64) @@ -45,18 +77,30 @@ std::ostringstream& Log::get(LogLevel level) void Log::flush() { - // Flush file. + // Flush file. Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; sFile.flush(); } void Log::close() { + // Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; if (sFile.is_open()) sFile.close(); } +Log::Log() +{ + // Log instance created. We grab the lock until destruction. + // This permits `Log().get(...) << msg << msg << msg;` to + // function as expected. + sLogMutex.lock(); +} + Log::~Log() { + // sLogMutex was (and still is) locked from the constructor Log(). mOutStringStream << std::endl; if (!sFile.is_open()) { @@ -72,4 +116,8 @@ Log::~Log() // If it's an error or the --debug flag has been set, then print to the console as well. if (mMessageLevel == LogError || sReportingLevel >= LogDebug) std::cerr << mOutStringStream.str(); + + // Release the lock, after any and all operations have been performed + // on mOutStringStream or sFile. + sLogMutex.unlock(); } diff --git a/es-core/src/Log.h b/es-core/src/Log.h index 3319fe771..887be03ff 100644 --- a/es-core/src/Log.h +++ b/es-core/src/Log.h @@ -15,6 +15,7 @@ #include #include #include +#include #include #define LOG(level) \ @@ -33,18 +34,21 @@ enum LogLevel { class Log { public: + // Constructor/deconstructor handle a lock, making get() thread-safe. + Log(); ~Log(); std::ostringstream& get(LogLevel level = LogInfo); - static LogLevel getReportingLevel() { return sReportingLevel; } - static void setReportingLevel(LogLevel level) { sReportingLevel = level; } - static std::string getLogPath() - { - return Utils::FileSystem::getHomePath() + "/.emulationstation/es_log.txt"; - } + static LogLevel getReportingLevel(); + static void setReportingLevel(LogLevel level); - static void flush(); + // getLogPath() is not thread-safe. + static std::string getLogPath(); + // init() is not thread-safe. static void init(); + + // The following static functions are thread-safe. + static void flush(); static void open(); static void close(); @@ -59,6 +63,7 @@ private: {LogDebug, "Debug"}}; static inline std::ofstream sFile; static inline LogLevel sReportingLevel = LogInfo; + static inline std::recursive_mutex sLogMutex; LogLevel mMessageLevel; }; From 517186bbe0e8b91638641b8c7a372885a330793c Mon Sep 17 00:00:00 2001 From: Joseph Geumlek Date: Thu, 23 Jun 2022 14:20:48 -0700 Subject: [PATCH 2/2] Make Log() instances only lock in ~Log(), and make the mutex non-recursive. --- es-core/src/Log.cpp | 61 +++++++++++++++++++++------------------------ es-core/src/Log.h | 12 ++++++--- 2 files changed, 37 insertions(+), 36 deletions(-) diff --git a/es-core/src/Log.cpp b/es-core/src/Log.cpp index b09e78049..07dbb8740 100644 --- a/es-core/src/Log.cpp +++ b/es-core/src/Log.cpp @@ -12,14 +12,14 @@ LogLevel Log::getReportingLevel() { // Static Log functions need to grab the lock. - std::unique_lock lock {sLogMutex}; + std::unique_lock lock {sLogMutex}; return sReportingLevel; } void Log::setReportingLevel(LogLevel level) { // Static Log functions need to grab the lock. - std::unique_lock lock {sLogMutex}; + std::unique_lock lock {sLogMutex}; sReportingLevel = level; } @@ -49,7 +49,7 @@ void Log::init() void Log::open() { // Static Log functions need to grab the lock. - std::unique_lock lock {sLogMutex}; + std::unique_lock lock {sLogMutex}; #if defined(_WIN64) sFile.open(Utils::String::stringToWideString(getLogPath()).c_str()); #else @@ -57,9 +57,25 @@ void Log::open() #endif } +void Log::flush() +{ + // Flush file. Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; + sFile.flush(); +} + +void Log::close() +{ + // Static Log functions need to grab the lock. + std::unique_lock lock {sLogMutex}; + if (sFile.is_open()) + sFile.close(); +} + std::ostringstream& Log::get(LogLevel level) { - // This function is not-static, lock is guarded by the Log() instance. + // This function is not-static, but only touches instance member variables. + // The lock is not needed. time_t t {time(nullptr)}; struct tm tm; #if defined(_WIN64) @@ -75,34 +91,19 @@ std::ostringstream& Log::get(LogLevel level) return mOutStringStream; } -void Log::flush() -{ - // Flush file. Static Log functions need to grab the lock. - std::unique_lock lock {sLogMutex}; - sFile.flush(); -} - -void Log::close() -{ - // Static Log functions need to grab the lock. - std::unique_lock lock {sLogMutex}; - if (sFile.is_open()) - sFile.close(); -} - -Log::Log() -{ - // Log instance created. We grab the lock until destruction. - // This permits `Log().get(...) << msg << msg << msg;` to - // function as expected. - sLogMutex.lock(); -} - Log::~Log() { - // sLogMutex was (and still is) locked from the constructor Log(). mOutStringStream << std::endl; + // Log() constructor does not need the lock. + // Log::get() does not need the lock. + // get(..) << msg << msg also does not need the lock, + // since get() returns the instance member mOutStringStream. + + // It is only now that we need the lock, to guard access to + // both std::cerr and sFile. + std::unique_lock lock {sLogMutex}; + if (!sFile.is_open()) { // Not open yet, print to stdout. std::cerr << "Error: Tried to write to log file before it was open, " @@ -116,8 +117,4 @@ Log::~Log() // If it's an error or the --debug flag has been set, then print to the console as well. if (mMessageLevel == LogError || sReportingLevel >= LogDebug) std::cerr << mOutStringStream.str(); - - // Release the lock, after any and all operations have been performed - // on mOutStringStream or sFile. - sLogMutex.unlock(); } diff --git a/es-core/src/Log.h b/es-core/src/Log.h index 887be03ff..833de1603 100644 --- a/es-core/src/Log.h +++ b/es-core/src/Log.h @@ -34,11 +34,14 @@ enum LogLevel { class Log { public: - // Constructor/deconstructor handle a lock, making get() thread-safe. - Log(); + // Deconstructor grabs the lock. ~Log(); + + // No lock needed for get() as it operates on and returns non-static members. std::ostringstream& get(LogLevel level = LogInfo); + // Lock is grabbed for sReportingLevel. + // This means level > Log::getReportingLevel() still requires the lock. static LogLevel getReportingLevel(); static void setReportingLevel(LogLevel level); @@ -46,10 +49,11 @@ public: static std::string getLogPath(); // init() is not thread-safe. static void init(); + // open() is not fully thread-safe, as it uses getLogPath(). + static void open(); // The following static functions are thread-safe. static void flush(); - static void open(); static void close(); protected: @@ -63,7 +67,7 @@ private: {LogDebug, "Debug"}}; static inline std::ofstream sFile; static inline LogLevel sReportingLevel = LogInfo; - static inline std::recursive_mutex sLogMutex; + static inline std::mutex sLogMutex; LogLevel mMessageLevel; };