feat: make logging machinery thread safe

CMakeLists.txt

@@ -304,6 +304,19 @@ if    (USE_ASAN)
 	endif (MSVC)
 endif (USE_ASAN)
 
+option(USE_TSAN "Build/link with thread sanitizer enabled" FALSE)
+if    (USE_TSAN)
+	if (UNIX AND NOT MINGW)
+		# mimalloc is incompatible with TSan unless built with MI_DEBUG_TSAN
+		# (clang-only); force it off so plain GCC/clang TSan builds just work.
+		set(USE_MIMALLOC OFF CACHE BOOL "disabled under TSan" FORCE)
+		# -fsanitize=thread: Enable ThreadSanitizer for detecting data races
+		# -fno-omit-frame-pointer / -g: keep usable stacks in race reports
+		add_compile_options("-fsanitize=thread" "-g" "-fno-omit-frame-pointer")
+		add_link_options("-fsanitize=thread")
+	endif (UNIX AND NOT MINGW)
+endif (USE_TSAN)
+
 ### Tracy related stuff
 option(RECOIL_DETAILED_TRACY_ZONING "Enable additional detailed tracy zones (only enable this for testing/debugging)" FALSE)
 if    (RECOIL_DETAILED_TRACY_ZONING)

rts/System/Log/Backend.cpp

@@ -6,6 +6,8 @@
 
 #include <algorithm>
 #include <array>
+#include <chrono>
+#include <mutex>
 
 #include "Backend.h"
 #include "DefaultFilter.h"
@@ -65,6 +67,59 @@ namespace log_formatter {
 }
 
 
+std::recursive_timed_mutex& log_getMutex() {
+	// construct-on-first-use and intentionally never destroyed, see
+	// the declaration in Backend.h.
+	static std::recursive_timed_mutex* logMutex = new std::recursive_timed_mutex();
+	return *logMutex;
+}
+
+
+// stacktrace-dump state, all per-thread so concurrent dumps on different threads
+// never clobber each other (see log_lockForStacktrace)
+static thread_local bool tlsLogMutexBypass = false; // read by LogMutexGuard
+static thread_local int  tlsStacktraceDepth = 0;
+static thread_local bool tlsStacktraceOwnsMutex = false;
+static thread_local bool tlsStacktraceSavedBypass = false;
+
+bool log_getMutexBypass() {
+	return tlsLogMutexBypass;
+}
+
+void log_lockForStacktrace() {
+	// only the outermost call on this thread establishes the lock/bypass state
+	if (tlsStacktraceDepth++ > 0)
+		return;
+
+	tlsStacktraceSavedBypass = tlsLogMutexBypass;
+
+	// bounded wait: long enough to ride out a normal in-progress log record,
+	// short enough not to stall a crash/hang dump if a thread is truly stuck
+	if (log_getMutex().try_lock_for(std::chrono::seconds(1))) {
+		tlsStacktraceOwnsMutex = true;
+	} else {
+		// could not acquire -> bypass the mutex on this thread so the dump
+		// cannot deadlock against whoever is holding it
+		tlsStacktraceOwnsMutex = false;
+		tlsLogMutexBypass = true;
+	}
+}
+
+void log_unlockForStacktrace() {
+	if (tlsStacktraceDepth == 0) // unbalanced; ignore
+		return;
+	if (--tlsStacktraceDepth > 0)
+		return;
+
+	if (tlsStacktraceOwnsMutex) {
+		tlsStacktraceOwnsMutex = false;
+		log_getMutex().unlock();
+	}
+
+	tlsLogMutexBypass = tlsStacktraceSavedBypass;
+}
+
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -77,11 +132,11 @@ static _threadlocal log_record_t prv_record = {{0}, "", "",  0, 0};
 
 extern void log_formatter_format(log_record_t* log, va_list arguments);
 
-void log_backend_registerSink(log_sink_ptr sink) { log_formatter::insert_sink(sink); }
-void log_backend_unregisterSink(log_sink_ptr sink) { log_formatter::remove_sink(sink); }
+void log_backend_registerSink(log_sink_ptr sink) { LogMutexGuard lock(log_getMutex()); log_formatter::insert_sink(sink); }
+void log_backend_unregisterSink(log_sink_ptr sink) { LogMutexGuard lock(log_getMutex()); log_formatter::remove_sink(sink); }
 
-void log_backend_registerCleanup(log_cleanup_ptr cleanupFunc) { log_formatter::insert_func(cleanupFunc); }
-void log_backend_unregisterCleanup(log_cleanup_ptr cleanupFunc) { log_formatter::remove_func(cleanupFunc); }
+void log_backend_registerCleanup(log_cleanup_ptr cleanupFunc) { LogMutexGuard lock(log_getMutex()); log_formatter::insert_func(cleanupFunc); }
+void log_backend_unregisterCleanup(log_cleanup_ptr cleanupFunc) { LogMutexGuard lock(log_getMutex()); log_formatter::remove_func(cleanupFunc); }
 
 
 /**
@@ -93,6 +148,8 @@ void log_backend_unregisterCleanup(log_cleanup_ptr cleanupFunc) { log_formatter:
 // formats and routes the record to all sinks
 void log_backend_record(int level, const char* section, const char* fmt, va_list arguments)
 {
+	LogMutexGuard lock(log_getMutex());
+
 	const auto& sinks = log_formatter::sinks;
 
 	if (log_formatter::numSinks == 0)
@@ -129,6 +186,8 @@ void log_backend_record(int level, const char* section, const char* fmt, va_list
 
 /// Passes on a cleanup request to all sinks
 void log_backend_cleanup() {
+	LogMutexGuard lock(log_getMutex());
+
 	const auto& funcs = log_formatter::cleanupFuncs;
 
 	for (size_t i = 0; i < log_formatter::numFuncs; i++) {

rts/System/Log/Backend.h

@@ -46,5 +46,75 @@ void log_backend_unregisterCleanup(log_cleanup_ptr cleanupFunc);
 } // extern "C"
 #endif
 
+
+#ifdef __cplusplus
+#include <mutex>
+
+/**
+ * The single mutex serializing the whole logging subsystem (filter config, sink
+ * registry, record dispatch, every sink). One shared lock rather than one per
+ * component, because the record path runs filter -> backend -> file sink while a
+ * file-sink rotate/truncate logs and re-enters from file sink, so separate locks
+ * would invert and deadlock.
+ *
+ * Recursive: many log functions log on their own error paths, re-entering on the
+ *            same thread. Recursive allows the same thread to grab the lock again
+ *            without deadlocking.
+ * 
+ * Timed: lets the crash/hang handler acquire it best-effort
+ *        (see log_lockForStacktrace).
+ * 
+ * Intentionally never destroyed: intended to be around until process exit
+ */
+std::recursive_timed_mutex& log_getMutex();
+
+/**
+ * Whether the calling thread is currently bypassing the log mutex. Set only by
+ * the crash/hang stacktrace handler (see log_lockForStacktrace) when it could
+ * not acquire the mutex; while set, this thread's LogMutexGuard does not lock,
+ * so the handler can never deadlock against a thread stuck holding the mutex.
+ */
+bool log_getMutexBypass();
+
+/**
+ * Scoped guard for the logging subsystem: locks log_getMutex() for its lifetime
+ * -- unless the calling thread is in stacktrace-bypass mode, in which case it
+ * does nothing (see log_getMutexBypass / log_lockForStacktrace).
+ */
+class LogMutexGuard {
+public:
+	explicit LogMutexGuard(std::recursive_timed_mutex& mtx): mutex(mtx) {
+		if (log_getMutexBypass())
+			return;
+		mutex.lock();
+		locked = true;
+	}
+	~LogMutexGuard() {
+		if (locked)
+			mutex.unlock();
+	}
+	LogMutexGuard(const LogMutexGuard&) = delete;
+	LogMutexGuard& operator=(const LogMutexGuard&) = delete;
+private:
+	std::recursive_timed_mutex& mutex;
+	bool locked = false;
+};
+
+/**
+ * Helpers to surround a crash/hang stacktrace dump. Calls must be balanced!
+ *
+ * Why a dump must never just block on the log mutex: it suspends other threads
+ * to walk their stacks, so a suspended thread that holds the mutex can never
+ * release it. Waiting on it would hang the handler forever.
+ * 
+ * To avoid that, we acquires the lock best-effort with a timeout
+ * - on success it is held until unlock 
+ * - on timeout -- a thread is stuck holding it, so we enter bypass mode and
+ *   skip the mutex instead of deadlocking
+ */
+void log_lockForStacktrace();
+void log_unlockForStacktrace();
+#endif
+
 #endif // LOG_BACKEND_H
 

rts/System/Log/DefaultFilter.cpp

@@ -2,11 +2,13 @@
 #include <cstdarg>
 #include <cassert>
 
+#include <atomic>
 #include <string>
 
 #include <algorithm>
 #include <stack>
 
+#include "Backend.h"
 #include "DefaultFilter.h"
 #include "Level.h"
 #include "Section.h"
@@ -36,9 +38,12 @@ struct log_filter_section_compare {
 
 
 namespace log_filter {
-	static int minLogLevel = LOG_LEVEL_ALL;
-	static int repeatLimit = 1;
+	// atomic so the common "min log level" check in log_frontend_isEnabled()
+	// can early-out without taking the full log mutex
+	static std::atomic<int> minLogLevel = LOG_LEVEL_ALL;
+	static std::atomic<int> repeatLimit = 1;
 
+	// guarded by log_getMutex()
 	static size_t numLevels = 0;
 	static size_t numSections = 0;
 
@@ -106,6 +111,8 @@ void log_filter_setRepeatLimit(int limit) { log_filter::repeatLimit = limit; }
 
 int log_filter_section_getMinLevel(const char* section)
 {
+	LogMutexGuard lock(log_getMutex());
+
 	int level = -1;
 
 	using P = decltype(log_filter::sectionMinLevels)::value_type;
@@ -127,6 +134,8 @@ int log_filter_section_getMinLevel(const char* section)
 // also by LuaUnsyncedCtrl::SetLogSectionFilterLevel
 void log_filter_section_setMinLevel(int level, const char* section)
 {
+	LogMutexGuard lock(log_getMutex());
+
 	log_filter_checkCompileTimeMinLevel(level);
 
 	auto& regSecs = log_filter::registeredSections;
@@ -189,6 +198,8 @@ void log_filter_section_setMinLevel(int level, const char* section)
 
 void log_enable_and_disable(const bool enable)
 {
+	LogMutexGuard lock(log_getMutex());
+
 	static std::stack<int> oldLevels;
 	int newLevel;
 
@@ -205,10 +216,14 @@ void log_enable_and_disable(const bool enable)
 }
 
 int log_filter_section_getNumRegisteredSections() {
+	LogMutexGuard lock(log_getMutex());
+
 	return log_filter::numSections;
 }
 
 const char* log_filter_section_getRegisteredIndex(int index) {
+	LogMutexGuard lock(log_getMutex());
+
 	if (index < 0)
 		return nullptr;
 	if (index >= static_cast<int>(log_filter::numSections))
@@ -237,8 +252,11 @@ static void log_filter_record(int level, const char* section, const char* fmt, v
 ///@{
 
 bool log_frontend_isEnabled(int level, const char* section) {
+	// lock-free fast path: global min-level is atomic, so the common rejected
+	// case never touches the log mutex
 	if (level < log_filter_global_getMinLevel())
 		return false;
+	// section lookup reads shared arrays under the log mutex (taken by the callee)
 	if (level < log_filter_section_getMinLevel(section))
 		return false;
 
@@ -250,6 +268,8 @@ void log_frontend_register_section(const char* section) {
 	if (LOG_SECTION_IS_DEFAULT(section))
 		return;
 
+	LogMutexGuard lock(log_getMutex());
+
 	auto& regSecs = log_filter::registeredSections;
 	auto regSec = std::lower_bound(regSecs.begin(), regSecs.begin() + log_filter::numSections, section, log_filter_section_compare());
 
@@ -275,6 +295,8 @@ void log_frontend_register_section(const char* section) {
 }
 
 void log_frontend_register_runtime_section(int level, const char* section_cstr_tmp) {
+	LogMutexGuard lock(log_getMutex());
+
 	const char* section_cstr = log_filter_section_getSectionCString(section_cstr_tmp);
 
 	log_frontend_register_section(section_cstr);
@@ -287,6 +309,8 @@ void log_frontend_record(int level, const char* section, const char* fmt, ...)
 	assert(level > LOG_LEVEL_ALL);
 	assert(level < LOG_LEVEL_NONE);
 
+	LogMutexGuard lock(log_getMutex());
+
 	// pass the log record on to the filter
 	va_list arguments;
 	va_start(arguments, fmt);
@@ -295,6 +319,8 @@ void log_frontend_record(int level, const char* section, const char* fmt, ...)
 }
 
 void log_frontend_cleanup() {
+	LogMutexGuard lock(log_getMutex());
+
 	log_backend_cleanup();
 }
 
@@ -309,11 +335,15 @@ void log_frontend_cleanup() {
 
 const char** log_filter_section_getRegisteredSet()
 {
+	LogMutexGuard lock(log_getMutex());
+
 	return &log_filter::registeredSections[0];
 }
 
 const char* log_filter_section_getSectionCString(const char* section_cstr_tmp)
 {
+	LogMutexGuard lock(log_getMutex());
+
 	// cache for log_frontend_register_runtime_section; services LuaUnsyced
 	static std::array<char[1024], MAX_LOG_SECTIONS> cache;
 	static spring::unordered_map<std::string, size_t> index;