From c1c8a3c072bbba9e8566aab6a6e9bb74f4a3bde4 Mon Sep 17 00:00:00 2001 From: Jonathan Bernard Date: Mon, 21 Sep 2026 17:43:45 -0500 Subject: [PATCH] Add failing ORC thread-safety regressions and run all suites with nimble test --- .gitignore | 4 ++ README.md | 9 ++++ namespaced_logging.nimble | 40 ++++++++++++++- tests/README.md | 53 ++++++++++++++++++++ tests/regressions.nim | 90 +++++++++++++++++++++++++++++++++ tests/run_tsan.sh | 16 ++++++ tests/thread_safety.nim | 103 ++++++++++++++++++++++++++++++++++++++ tests/writer_child.nim | 29 +++++++++++ 8 files changed, 342 insertions(+), 2 deletions(-) create mode 100644 tests/README.md create mode 100644 tests/regressions.nim create mode 100644 tests/run_tsan.sh create mode 100644 tests/thread_safety.nim create mode 100644 tests/writer_child.nim diff --git a/.gitignore b/.gitignore index 4624793..cee78c5 100644 --- a/.gitignore +++ b/.gitignore @@ -1,6 +1,10 @@ .*.sw? nimcache/ tests/tests +tests/bin/ src/namespaced_logging.out src/namespaced_logging/autoconfigured .worktrees +nimble.develop +nimble.paths +nimbledeps diff --git a/README.md b/README.md index 9e7d331..1ff58be 100644 --- a/README.md +++ b/README.md @@ -459,6 +459,15 @@ As much as possible, avoid complex operations that might themselves fail. Don't do heavy operations like database writes, complex network operations, or file system operations that might fail and cause cascading errors. +## Testing + +Run `nimble test` for all unit, regression, and ThreadSanitizer ownership tests. +It runs every suite even when an earlier suite fails. For focused debugging, +use `nimble testUnit`, `nimble testRegression`, or `nimble testThreadSafety`. +The regression tests currently expose known defects and are expected to fail +until those defects are fixed. See [tests/README.md](tests/README.md) for commands, +requirements, and coverage limitations. + [log4j]: https://logging.apache.org/log4j/2.x/ [logback]: https://logback.qos.ch/ [effective logging level]: https://logback.qos.ch/manual/architecture.html#effectiveLevel diff --git a/namespaced_logging.nimble b/namespaced_logging.nimble index 9b376ae..b802557 100644 --- a/namespaced_logging.nimble +++ b/namespaced_logging.nimble @@ -14,6 +14,42 @@ requires @["nim >= 2.2.0", "zero_functional"] # from https://git.jdb-software.com/jdb/nim-packages requires "timeutils" -task test, "Run unittests for the package.": - exec "nimble c src/namespaced_logging.nim" +proc runUnitTests() = + exec "nimble c --mm:orc --threads:on src/namespaced_logging.nim" exec "src/namespaced_logging.out" + +proc runRegressionTests() = + exec "nimble c --mm:orc --threads:on -d:multithreaded --out:tests/bin/writer_child tests/writer_child.nim" + exec "nimble c --mm:orc --threads:on --out:tests/bin/regressions tests/regressions.nim" + exec "tests/bin/regressions" + +proc runThreadSafetyTests() = + exec "nimble c --mm:orc --threads:on --passC:-fsanitize=thread --passC:-g --passL:-fsanitize=thread --out:tests/bin/thread_safety tests/thread_safety.nim" + exec "bash tests/run_tsan.sh tests/bin/thread_safety" + +task test, "Run all tests, including ThreadSanitizer, and report all failing suites.": + var failedSuites: seq[string] = @[] + template runSuite(name: string, action: untyped) = + echo "Running test suite: ", name + try: + action + echo "PASS: ", name + except OSError as err: + echo "FAIL: ", name, ": ", err.msg + failedSuites.add(name) + + runSuite("unit", runUnitTests()) + runSuite("regression", runRegressionTests()) + runSuite("thread safety", runThreadSafetyTests()) + if failedSuites.len > 0: + echo "Failed test suites: ", failedSuites + quit(1) + +task testUnit, "Run the existing embedded unit tests under ORC.": + runUnitTests() + +task testRegression, "Run ownership, configuration, and shutdown regressions.": + runRegressionTests() + +task testThreadSafety, "Run ORC ownership tests with ThreadSanitizer (Linux).": + runThreadSafetyTests() diff --git a/tests/README.md b/tests/README.md new file mode 100644 index 0000000..04da232 --- /dev/null +++ b/tests/README.md @@ -0,0 +1,53 @@ +# Regression tests + +These tests assert the intended behavior. Known bugs are ordinary failures, +not expected failures: the tasks should become green as the defects are fixed. + +Run from the repository root: + +| Command | Coverage | +| --- | --- | +| `nimble test` | All unit, regression, and ThreadSanitizer tests under ORC with threads enabled | +| `nimble testUnit` | Existing embedded unit tests | +| `nimble testRegression` | Configuration freshness, refresh failure recovery, appender-state cleanup, and writer shutdown | +| `nimble testThreadSafety` | Separate ThreadSanitizer processes for service ownership, custom state, and formatter closures, plus an independent-service control | + +`nimble test` attempts every suite even if an earlier suite fails to compile or +run, summarizes the failing suites, and exits unsuccessfully if any suite fails. +The subset commands use the same build and execution procedures as the full run. + +Executables are generated in ignored `tests/bin/`. The shutdown child is built +with `-d:multithreaded`; `--threads:on` alone does not enable background writers. +The other tests do not need background I/O to exercise ownership. + +The full run and the sanitizer subset require Linux, Bash, GNU `timeout`, and a +C compiler and runtime supporting `-fsanitize=thread`. The sanitizer instruments +the generated Nim C code, including the ORC runtime. A sanitizer report, timeout, +crash, or runtime startup +failure causes a nonzero result; consult the diagnostic to distinguish these. +Each scenario runs separately so one failure does not hide another. To inspect +one scenario after building: + +```sh +TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s tests/bin/thread_safety service +``` + +The worker start barrier ensures argument setup finishes before the concurrent +operations begin. Parent owners survive until all workers join. Custom-state +and closure tests only read application data; their concurrent writes are the +implicit ownership operations caused by cloning and destruction. The independent +case creates a separate service inside each worker and should pass. Custom-state +and formatter cloning is serialized with a lock, matching configuration refresh; +the copied appenders are used and destroyed outside that lock. + +The three in-process regression tests are deterministic. Shutdown tests launch +a fresh process for each destination and check all 10,000 messages after normal +exit, using isolated temporary paths and a 15-second deadline. They exercise the +real exit hook without sleeps to hide queued-message loss. Like the race tests, +the shutdown failure can depend on scheduling; a passing run is not proof of +thread safety or reliable draining. + +This suite does not yet force an active producer/channel-close race, separately +exercise the shared `testutil.LoggedMessages` graph, or exhaust ORC cycle-collector +interleavings. It provides targeted regressions for the reproduced ownership +defects and the configuration, cleanup, and shutdown findings. diff --git a/tests/regressions.nim b/tests/regressions.nim new file mode 100644 index 0000000..c567f5e --- /dev/null +++ b/tests/regressions.nim @@ -0,0 +1,90 @@ +import std/[os, osproc, strutils, tempfiles, unittest] +import ../src/namespaced_logging + +type + CloneControl = object + failNext: bool + FallibleAppender = ref object of LogAppender + control: ptr CloneControl + +method clone(app: FallibleAppender): LogAppender {.gcsafe.} = + if app.control.failNext: + app.control.failNext = false + raise newException(ValueError, "injected clone failure") + FallibleAppender(control: app.control) + +type + LifetimeProbeObj = object + destroyed: ptr int + LifetimeProbe = ref LifetimeProbeObj + +proc `=destroy`(probe: LifetimeProbeObj) = + inc probe.destroyed[] + +proc ignoreMessage(state: LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} = + discard + +proc createAndReleaseService(destroyed: ptr int) = + var service = initLogService() + service.addAppender(initCustomLogAppender( + LifetimeProbe(destroyed: destroyed), ignoreMessage)) + # All owning handles leave scope here. No thread or cycle is involved. + +suite "ORC ownership and configuration regressions": + test "isEnabled observes a namespace change before any log call": + var service = initLogService() + service.setThreshold("worker", lvlError) + let local = service.threadLocalRef() + let logger = local.getLogger("worker") + check not logger.isEnabled(lvlInfo) + + # Simulate a change from another service handle without introducing a + # reference-count race into this deterministic configuration test. + service.setThreshold("worker", lvlInfo) + check logger.isEnabled(lvlInfo) + + test "a failed refresh is retried without another configuration change": + var control: CloneControl + var service = initLogService() + service.addAppender(FallibleAppender(control: addr control)) + let local = service.threadLocalRef() + discard local.getLogger("worker") + service.setRootThreshold(lvlInfo) + + control.failNext = true + expect ValueError: + local.ensureFreshness() + + # clone now succeeds; the failed refresh must not have marked the + # incomplete local configuration as current. + local.ensureFreshness() + check local.appenders().len == 1 + + test "releasing the service releases state owned by its appenders": + var destroyed = 0 + createAndReleaseService(addr destroyed) + check destroyed == 1 + +suite "Background writer shutdown regressions": + for destination in ["file", "console"]: + test destination & " writer drains accepted messages at normal process exit": + let directory = createTempDir("namespaced_logging_shutdown_", "") + let outputPath = directory / "messages.log" + defer: removeDir(directory) + + let child = startProcess(parentDir(getAppFilename()) / "writer_child", + args = [destination, outputPath], options = {poParentStreams}) + defer: close(child) + let exitCode = child.waitForExit(15_000) + if exitCode == -1: + child.kill() + discard child.waitForExit() + check exitCode == 0 + require fileExists(outputPath) + + let received = readFile(outputPath).splitLines() + # Check every record and its order, not just file existence. splitLines + # includes one final empty item because each record ends with a newline. + check received.len == 10_001 + for i in 0 ..< min(10_000, received.len - 1): + check received[i] == "message " & $i diff --git a/tests/run_tsan.sh b/tests/run_tsan.sh new file mode 100644 index 0000000..a49ee5f --- /dev/null +++ b/tests/run_tsan.sh @@ -0,0 +1,16 @@ +#!/usr/bin/env bash +set -u + +binary=${1:?Expected the ThreadSanitizer test executable} +result=0 +for scenario in independent service custom-state formatter; do + echo "ThreadSanitizer scenario: $scenario" + if TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s "$binary" "$scenario"; then + echo "PASS: $scenario" + else + code=$? + echo "FAIL: $scenario (exit $code)" >&2 + result=1 + fi +done +exit "$result" diff --git a/tests/thread_safety.nim b/tests/thread_safety.nim new file mode 100644 index 0000000..d5e449b --- /dev/null +++ b/tests/thread_safety.nim @@ -0,0 +1,103 @@ +## Run each scenario in its own ThreadSanitizer-instrumented process. +## Success means no race was reported; a crash is not required to expose UB. +import std/[atomics, locks, os] +import ../src/namespaced_logging + +const iterations = 1_000 +var start: Atomic[bool] +var cloneLock: Lock + +proc awaitStart() = + while not start.load(): + discard + +proc serviceWorker(service: LogService) {.thread.} = + awaitStart() + for i in 0 ..< iterations: + let local = service.threadLocalRef() + let logger = local.getLogger("worker") + doAssert logger.isEnabled(lvlInfo) + +proc independentWorker() {.thread.} = + awaitStart() + var service = initLogService() + service.setThreshold("worker", lvlInfo) + for i in 0 ..< iterations: + let local = service.threadLocalRef() + let logger = local.getLogger("worker") + doAssert logger.isEnabled(lvlInfo) + +type + CustomState = ref object + value: int + StatefulAppender = CustomLogAppender[CustomState] + +proc ignoreMessage(state: CustomState, msg: LogMessage) {.gcsafe, noconv.} = + discard + +proc stateWorker(source: ptr StatefulAppender) {.thread.} = + awaitStart() + for i in 0 ..< iterations: + var copied: StatefulAppender + withLock cloneLock: + copied = StatefulAppender(clone(source[])) + doAssert copied.state.value == 42 + +proc makeFormatter(prefix: string): LogMessageFormatter = + result = proc(msg: LogMessage): string {.gcsafe.} = prefix & msg.msg + +proc formatterWorker(source: ptr ConsoleLogAppender) {.thread.} = + awaitStart() + # This formatter only needs msg. Avoid clock/timezone initialization so + # sanitizer diagnostics identify closure ownership rather than libc state. + let msg = LogMessage(msg: "message") + for i in 0 ..< iterations: + var copied: ConsoleLogAppender + withLock cloneLock: + copied = ConsoleLogAppender(clone(source[])) + doAssert copied.formatter(msg) == "prefix: message" + +proc main() = + doAssert paramCount() == 1 + initLock(cloneLock) + defer: deinitLock(cloneLock) + case paramStr(1) + of "independent": + var workers: array[4, Thread[void]] + for i in 0 ..< workers.len: + createThread(workers[i], independentWorker) + start.store(true) + joinThreads(workers) + of "service": + var service = initLogService() + service.setThreshold("worker", lvlInfo) + service.addAppender(initConsoleLogAppender()) + var workers: array[4, Thread[LogService]] + for i in 0 ..< workers.len: + createThread(workers[i], serviceWorker, service) + # No parent-side copying/configuration changes overlap the workers. + # The parent retains service and all thread argument storage until join. + start.store(true) + joinThreads(workers) + of "custom-state": + var source = initCustomLogAppender(CustomState(value: 42), ignoreMessage) + var workers: array[4, Thread[ptr StatefulAppender]] + for i in 0 ..< workers.len: + createThread(workers[i], stateWorker, addr source) + start.store(true) + joinThreads(workers) + of "formatter": + var source = initConsoleLogAppender() + source.formatter = makeFormatter("prefix: ") + var workers: array[4, Thread[ptr ConsoleLogAppender]] + for i in 0 ..< workers.len: + createThread(workers[i], formatterWorker, addr source) + start.store(true) + joinThreads(workers) + else: + raise newException(ValueError, "unknown thread safety scenario") + +# The pointer-based scenarios borrow immutable source appenders whose owner +# outlives all workers. This isolates clone/destruction races from LogService +# copying and from ordinary unsynchronized application-state mutation. +main() diff --git a/tests/writer_child.nim b/tests/writer_child.nim new file mode 100644 index 0000000..c29210d --- /dev/null +++ b/tests/writer_child.nim @@ -0,0 +1,29 @@ +import std/os +import ../src/namespaced_logging + +when not defined(multithreaded): + {.error: "Compile this fixture with -d:multithreaded to exercise writer threads".} + +proc formatLine(msg: LogMessage): string {.gcsafe.} = msg.msg & "\n" + +proc main() = + doAssert paramCount() == 2 + var service = initLogService() + case paramStr(1) + of "file": + service.addAppender(initFileLogAppender(paramStr(2))) + of "console": + # Keep stdout open through the library's exit hook. Redirecting it to a + # file also prevents a full parent/child pipe from blocking the writer. + doAssert open(stdout, paramStr(2), fmWrite) + service.addAppender(initConsoleLogAppender(formatter = formatLine)) + else: + raise newException(ValueError, "unknown writer destination") + + let local = service.threadLocalRef() + let logger = local.getLogger("shutdown") + for i in 0 ..< 10_000: + logger.info("message " & $i) + # No sleep or explicit flush: normal exit must preserve accepted messages. + +main()