From 6f56b545f605882ac92ac7949cfc5a0c5f6be904 Mon Sep 17 00:00:00 2001 From: Bruno Da Silva Date: Sun, 21 Jun 2026 00:30:03 +0000 Subject: [PATCH 1/2] feat: make logging machinery thread safe --- rts/System/Log/Backend.cpp | 67 +++++++++++++++++++-- rts/System/Log/Backend.h | 70 ++++++++++++++++++++++ rts/System/Log/DefaultFilter.cpp | 34 ++++++++++- rts/System/Log/FileSink.cpp | 18 +++++- rts/System/Platform/Linux/CrashHandler.cpp | 31 ++++++++-- rts/System/Platform/Win/CrashHandler.cpp | 9 +++ 6 files changed, 216 insertions(+), 13 deletions(-) diff --git a/rts/System/Log/Backend.cpp b/rts/System/Log/Backend.cpp index 9a3e925aef1..ef216a443cd 100644 --- a/rts/System/Log/Backend.cpp +++ b/rts/System/Log/Backend.cpp @@ -6,6 +6,8 @@ #include #include +#include +#include #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++) { diff --git a/rts/System/Log/Backend.h b/rts/System/Log/Backend.h index b41e9908096..54d91816f46 100644 --- a/rts/System/Log/Backend.h +++ b/rts/System/Log/Backend.h @@ -46,5 +46,75 @@ void log_backend_unregisterCleanup(log_cleanup_ptr cleanupFunc); } // extern "C" #endif + +#ifdef __cplusplus +#include + +/** + * 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 diff --git a/rts/System/Log/DefaultFilter.cpp b/rts/System/Log/DefaultFilter.cpp index cf0c3939d29..b1d148ca033 100644 --- a/rts/System/Log/DefaultFilter.cpp +++ b/rts/System/Log/DefaultFilter.cpp @@ -2,11 +2,13 @@ #include #include +#include #include #include #include +#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 minLogLevel = LOG_LEVEL_ALL; + static std::atomic 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 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(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 cache; static spring::unordered_map index; diff --git a/rts/System/Log/FileSink.cpp b/rts/System/Log/FileSink.cpp index 751011bbe14..c4b91ae378a 100644 --- a/rts/System/Log/FileSink.cpp +++ b/rts/System/Log/FileSink.cpp @@ -65,6 +65,10 @@ namespace log_file { typedef std::vector LogFilesMap; ~LogFilesContainer() { + // hold the lock so a concurrent logger can't see validTracker==true + // and touch the container mid-destruction (removeAllLogFiles + // re-locks recursively) + LogMutexGuard lock(log_getMutex()); log_file_removeAllLogFiles(); validTracker = false; } @@ -199,6 +203,8 @@ void log_file_addLogFile( ) { assert(filePath != nullptr); + LogMutexGuard lock(log_getMutex()); + auto& logFiles = log_file::getLogFiles(); const std::string sectionsStr = (sections == nullptr) ? "" : sections; @@ -235,6 +241,8 @@ void log_file_addLogFile( void log_file_removeLogFile(const char* filePath) { assert(filePath != nullptr); + LogMutexGuard lock(log_getMutex()); + auto& logFiles = log_file::getLogFiles(); const auto pred = [](const log_file::LogFilePair& a, const log_file::LogFilePair& b) { return (a.first < b.first); }; @@ -257,6 +265,8 @@ void log_file_removeLogFile(const char* filePath) { } void log_file_removeAllLogFiles() { + LogMutexGuard lock(log_getMutex()); + auto& logFiles = log_file::getLogFiles(); for (auto& logFilePair: logFiles) { @@ -268,6 +278,8 @@ void log_file_removeAllLogFiles() { FILE* log_file_getLogFileStream(const char* filePath) { + LogMutexGuard lock(log_getMutex()); + const auto& logFiles = log_file::getLogFiles(); for (const auto& p: logFiles) { @@ -280,8 +292,6 @@ FILE* log_file_getLogFileStream(const char* filePath) { return nullptr; } - - /** * @name logging_sink_file * ILog.h sink implementation. @@ -291,6 +301,8 @@ FILE* log_file_getLogFileStream(const char* filePath) { /// Records a log entry static void log_sink_record_file(int level, const char* section, const char* record) { + LogMutexGuard lock(log_getMutex()); + if (log_file::validTracker && log_file::isActivelyLogging()) { // write buffer to log file log_file::writeBufferToFiles(); @@ -305,6 +317,8 @@ static void log_sink_record_file(int level, const char* section, const char* rec /// Cleans up all log streams, by flushing them. static void log_sink_cleanup_file() { + LogMutexGuard lock(log_getMutex()); + if (!log_file::isActivelyLogging()) return; diff --git a/rts/System/Platform/Linux/CrashHandler.cpp b/rts/System/Platform/Linux/CrashHandler.cpp index 062e399a776..d046d7ea5e6 100644 --- a/rts/System/Platform/Linux/CrashHandler.cpp +++ b/rts/System/Platform/Linux/CrashHandler.cpp @@ -25,6 +25,7 @@ #include "System/FileSystem/FileSystem.h" #include "System/SpringExitCode.h" #include "System/Log/ILog.h" +#include "System/Log/Backend.h" #include "System/Log/LogSinkHandler.h" #include "System/LogOutput.h" #include "System/StringUtil.h" @@ -703,7 +704,10 @@ namespace CrashHandler * So, it is used by both the HaltedStacktrace and the SuspendedStacktrace. * Since this method is pure implementation, it's */ - int thread_unwind(ucontext_t* uc, void** iparray, StackTrace& stacktrace) + // unwInitErrOut: if set, the unw_init_local() error is returned here instead + // of logged, so SuspendedStacktrace can report it after Resume() -- logging + // while a thread is suspended could deadlock on the log mutex it may hold. + int thread_unwind(ucontext_t* uc, void** iparray, StackTrace& stacktrace, int* unwInitErrOut = nullptr) { assert(iparray != nullptr); @@ -749,7 +753,10 @@ namespace CrashHandler #endif if (err != 0) { - LOG_L(L_ERROR, "unw_init_local returned %d", err); + if (unwInitErrOut != nullptr) + *unwInitErrOut = err; // caller logs this once it is safe to do so + else + LOG_L(L_ERROR, "unw_init_local returned %d", err); return 0; } @@ -855,10 +862,17 @@ namespace CrashHandler // process and analyse the raw stack trace void* iparray[MAX_STACKTRACE_DEPTH]; + // no logging between Suspend/Resume: a LOG_*() could deadlock on the + // log mutex if the suspended thread holds it; report after Resume() + int unwInitErr = 0; + ctls->Suspend(); - const int numLines = thread_unwind(&ctls->ucontext, iparray, stacktrace); + const int numLines = thread_unwind(&ctls->ucontext, iparray, stacktrace, &unwInitErr); ctls->Resume(); + if (unwInitErr != 0) + LOG_L(L_ERROR, "unw_init_local returned %d", unwInitErr); + LOG_L(L_DEBUG, "[%s][2]", __func__); if (numLines > MAX_STACKTRACE_DEPTH) @@ -931,8 +945,15 @@ namespace CrashHandler } - void PrepareStacktrace(const int logLevel) {} - void CleanupStacktrace(const int logLevel) { LOG_CLEANUP(); } + void PrepareStacktrace(const int logLevel) { + // lock the dump against log rotation / other loggers, or bypass the + // mutex on this thread if it cannot be acquired (see log_lockForStacktrace) + log_lockForStacktrace(); + } + void CleanupStacktrace(const int logLevel) { + LOG_CLEANUP(); + log_unlockForStacktrace(); + } void HandleSignal(int signal, siginfo_t* siginfo, void* pctx) diff --git a/rts/System/Platform/Win/CrashHandler.cpp b/rts/System/Platform/Win/CrashHandler.cpp index c4d1b2fa948..58e8e423736 100755 --- a/rts/System/Platform/Win/CrashHandler.cpp +++ b/rts/System/Platform/Win/CrashHandler.cpp @@ -8,6 +8,7 @@ #include "System/Platform/CrashHandler.h" #include "System/Platform/errorhandler.h" #include "System/Log/ILog.h" +#include "System/Log/Backend.h" #include "System/Log/FileSink.h" #include "System/Log/LogSinkHandler.h" #include "System/LogOutput.h" @@ -400,6 +401,12 @@ void Stacktrace(Threading::NativeThreadHandle thread, const std::string& threadN void PrepareStacktrace(const int logLevel) { EnterCriticalSection(&stackLock); + + // lock the dump against log rotation and other loggers, so the streams + // we write stay valid and no suspended thread holds the log mutex (or bypass + // it if it can't be acquired; see log_lockForStacktrace) + log_lockForStacktrace(); + InitImageHlpDll(); // sidestep any kind of hidden allocation which might cause a deadlock @@ -423,6 +430,8 @@ void CleanupStacktrace(const int logLevel) { SymCleanup(GetCurrentProcess()); imageHelpInitialised = false; + log_unlockForStacktrace(); + LeaveCriticalSection(&stackLock); } From a78fea008191938e14939c7c64567f70fb130819 Mon Sep 17 00:00:00 2001 From: Bruno Da Silva Date: Sun, 21 Jun 2026 18:49:34 +0000 Subject: [PATCH 2/2] test: add multithreaded logging tests runnable under TSan Add three Catch2 cases to TestILog.cpp that stress the logging machinery concurrently: - ConcurrentRecordDispatch: N threads flooding records at mixed levels/sections - ConcurrentSinkRegistryChurn: writers logging while a mutator churns the shared logFiles - ConcurrentFilterChanges: writers logging on a section while another thread changes its filter level and re-registers it Wire ThreadSanitizer: - new USE_TSAN CMake option (whole-engine TSan). Similar to USE_ASAN. - test_ILog is built with -fsanitize=thread by default on Linux so the cases can be run with `./test/test_ILog "[multithreaded]"` without a separate build tree. Co-Authored-By: Claude Opus 4.8 (1M context) --- CMakeLists.txt | 13 ++ test/CMakeLists.txt | 11 ++ test/engine/System/Log/TestILog.cpp | 207 ++++++++++++++++++++++++++++ 3 files changed, 231 insertions(+) diff --git a/CMakeLists.txt b/CMakeLists.txt index d016d27287c..821a219dce5 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 099dc4dbe71..367eec5d1c6 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -140,6 +140,17 @@ endif() add_spring_test(${test_name} "${test_src}" "${test_libs}" "") + # Always build the ILog test with ThreadSanitizer so its multithreaded cases + # (tagged [.multithreaded]) can detect logging data races without a separate + # -DUSE_TSAN build tree. test_ILog does not link mimalloc, so this is safe. + # Skipped where it can't apply: TSan is unsupported on MSVC/MinGW and mutually + # exclusive with ASan; when the whole build is already TSan (USE_TSAN) the + # global flags already cover it. + if (UNIX AND NOT MINGW AND NOT USE_ASAN AND NOT USE_TSAN) + target_compile_options(test_ILog PRIVATE -fsanitize=thread -g -fno-omit-frame-pointer) + target_link_options(test_ILog PRIVATE -fsanitize=thread) + endif() + ################################################################################ ### SyncedPrimitive set(test_name SyncedPrimitive) diff --git a/test/engine/System/Log/TestILog.cpp b/test/engine/System/Log/TestILog.cpp index cb8d4b3e4a1..c744244e9e1 100644 --- a/test/engine/System/Log/TestILog.cpp +++ b/test/engine/System/Log/TestILog.cpp @@ -3,11 +3,15 @@ #include "System/Log/FileSink.h" #include "System/Log/StreamSink.h" #include "System/Log/LogUtil.h" +#include "System/Log/DefaultFilter.h" #include #include #include +#include +#include +#include @@ -231,3 +235,206 @@ TEST_CASE("IsEnabled") TLOG_SL( "other-one-time-section", L_DEBUG, "Testing LOG_IS_ENABLED_S"); } + +//////////////////////////////////////////////////////////////////////////////// +// Multithreaded logging tests. +// +// These prove the logging machinery is race-free under ThreadSanitizer. On +// Linux test_ILog is built with -fsanitize=thread by default. +// They are tagged hidden ([.multithreaded]) so the normal `make check` run +// skips them; run them explicitly by naming the tag: +// ./test/test_ILog "[multithreaded]" +// Each case asserts only after join (Catch2 macros are not thread-safe) and +// restores any global logging state it mutates so later cases are unaffected. + +namespace { + // barrier so all worker threads start hammering at once + void waitForStart(const std::atomic& startFlag) { + while (!startFlag.load()) + std::this_thread::yield(); + } +} + +// N threads emit a flood of records at mixed levels/sections. +TEST_CASE("ConcurrentRecordDispatch", "[.multithreaded]") +{ + constexpr int NUM_THREADS = 8; + constexpr int MSGS_PER_THREAD = 2000; + + std::atomic startFlag{false}; + std::atomic completed{0}; + + auto worker = [&](int tid) { + waitForStart(startFlag); + for (int i = 0; i < MSGS_PER_THREAD; ++i) { + switch ((tid + i) % 5) { + case 0: LOG_L(L_DEBUG, "[T%d] msg %d", tid, i); break; + case 1: LOG_L(L_INFO, "[T%d] msg %d", tid, i); break; + case 2: LOG_L(L_WARNING, "[T%d] msg %d", tid, i); break; + case 3: LOG_L(L_ERROR, "[T%d] msg %d", tid, i); break; + case 4: LOG_SL(LOG_SECTION_DEFINED, L_INFO, "[T%d] sec msg %d", tid, i); break; + } + } + completed.fetch_add(1); + }; + + std::vector threads; + for (int t = 0; t < NUM_THREADS; ++t) + threads.emplace_back(worker, t); + + startFlag.store(true); + for (auto& th : threads) + th.join(); + + CHECK(completed.load() == NUM_THREADS); + + ls.logStream.str(std::string()); // don't leak content into later exact-match cases +} + +// Writer threads log continuously while a mutator thread churns the shared +// logFiles container (add/remove of a separate file) that the record path +// iterates. +TEST_CASE("ConcurrentSinkRegistryChurn", "[.multithreaded]") +{ + constexpr int NUM_WRITERS = 6; + constexpr int WRITE_ITERS = 4000; + constexpr int CHURN_ITERS = 400; + + char* tmp = tmpnam(nullptr); + REQUIRE(tmp != nullptr); + const std::string churnFile = tmp; + + std::atomic startFlag{false}; + std::atomic completed{0}; + + auto writer = [&](int tid) { + waitForStart(startFlag); + for (int i = 0; i < WRITE_ITERS; ++i) + LOG_L(L_INFO, "[W%d] churn-write %d", tid, i); + completed.fetch_add(1); + }; + + auto mutator = [&]() { + waitForStart(startFlag); + for (int i = 0; i < CHURN_ITERS; ++i) { + log_file_addLogFile(churnFile.c_str()); + log_file_removeLogFile(churnFile.c_str()); + } + }; + + std::vector threads; + for (int t = 0; t < NUM_WRITERS; ++t) + threads.emplace_back(writer, t); + threads.emplace_back(mutator); + + startFlag.store(true); + for (auto& th : threads) + th.join(); + + CHECK(completed.load() == NUM_WRITERS); + + // cleanup: deregister and delete the churn file + log_file_removeLogFile(churnFile.c_str()); + remove(churnFile.c_str()); + ls.logStream.str(std::string()); +} + +// Reader threads read a section's min level while one thread flips that level. +TEST_CASE("ConcurrentFilterChanges", "[.multithreaded]") +{ + constexpr int NUM_READERS = 6; + constexpr int READ_ITERS = 200000; + constexpr int FLIP_ITERS = 200000; + + // the section's default level (it is not overridden at this point), used as + // the "erase" value below + const int savedLevel = log_filter_section_getMinLevel(LOG_SECTION_DEFINED); + const int insertLevel = (savedLevel != LOG_LEVEL_WARNING) ? LOG_LEVEL_WARNING : LOG_LEVEL_ERROR; + + std::atomic startFlag{false}; + std::atomic completed{0}; + + auto reader = [&](int /*tid*/) { + waitForStart(startFlag); + int sink = 0; + for (int i = 0; i < READ_ITERS; ++i) + sink += log_filter_section_getMinLevel(LOG_SECTION_DEFINED); + completed.fetch_add(1); + (void) sink; + }; + + auto flipper = [&]() { + waitForStart(startFlag); + // Alternate a non-default level (inserts into sectionMinLevels) with the + // section default (erases it) so the shared array is mutated continuously. + // TODO: simplify to just any two log levels after #3052 merges + for (int i = 0; i < FLIP_ITERS; ++i) + log_filter_section_setMinLevel((i & 1) ? insertLevel : savedLevel, LOG_SECTION_DEFINED); + }; + + std::vector threads; + for (int t = 0; t < NUM_READERS; ++t) + threads.emplace_back(reader, t); + threads.emplace_back(flipper); + + startFlag.store(true); + for (auto& th : threads) + th.join(); + + CHECK(completed.load() == NUM_READERS); + + // restore the section level we churned so later cases see the original state + log_filter_section_setMinLevel(savedLevel, LOG_SECTION_DEFINED); + ls.logStream.str(std::string()); +} + +// Writer threads log while one thread flips the global min level and repeat +// limit. Those are atomics specifically so the log_frontend_isEnabled() fast +// path can read them without taking the log mutex; this exercises that +// write-while-read (a non-atomic version would race here under TSan). +TEST_CASE("ConcurrentGlobalFilterChanges", "[.multithreaded]") +{ + constexpr int NUM_WRITERS = 6; + constexpr int WRITE_ITERS = 4000; + constexpr int FLIP_ITERS = 2000; + + const int savedLevel = log_filter_global_getMinLevel(); + const int savedRepeat = log_filter_getRepeatLimit(); + + std::atomic startFlag{false}; + std::atomic completed{0}; + + auto writer = [&](int tid) { + waitForStart(startFlag); + // every LOG_* reads the atomic global min level on the fast path; as the + // flipper toggles it, some records are rejected there and some pass on + for (int i = 0; i < WRITE_ITERS; ++i) + LOG_L(L_INFO, "[G%d] global %d", tid, i); + completed.fetch_add(1); + }; + + auto flipper = [&]() { + waitForStart(startFlag); + for (int i = 0; i < FLIP_ITERS; ++i) { + log_filter_global_setMinLevel((i & 1) ? LOG_LEVEL_DEBUG : LOG_LEVEL_WARNING); + log_filter_setRepeatLimit((i & 1) ? 1 : 5); + } + }; + + std::vector threads; + for (int t = 0; t < NUM_WRITERS; ++t) + threads.emplace_back(writer, t); + threads.emplace_back(flipper); + + startFlag.store(true); + for (auto& th : threads) + th.join(); + + CHECK(completed.load() == NUM_WRITERS); + + // restore the globals we churned so later cases see the original state + log_filter_global_setMinLevel(savedLevel); + log_filter_setRepeatLimit(savedRepeat); + ls.logStream.str(std::string()); +} +