From 761bd6679361f233c4cd16b61c996f0376e65bba Mon Sep 17 00:00:00 2001 From: Jonathan Bernard Date: Tue, 22 Sep 2026 07:18:13 -0500 Subject: [PATCH] Separate shared service ownership from thread-local logging caches --- README.md | 129 ++++++++++++-------- src/namespaced_logging.nim | 244 +++++++++++++++++++++++-------------- tests/README.md | 25 +++- tests/regressions.nim | 72 ++++++++++- tests/run_tsan.sh | 2 +- tests/thread_safety.nim | 71 +++++++++++ 6 files changed, 386 insertions(+), 157 deletions(-) diff --git a/README.md b/README.md index 1ff58be..3fde503 100644 --- a/README.md +++ b/README.md @@ -201,53 +201,58 @@ func initCustomLogAppender*[T]( The `state` field allows you to explicitly pass in any data that is required for the custom functionality. -*TODO: rethink this. I chose this to avoid GC-safety issues copying closures -across threads, but maybe I don't need this separate, explicit state field.* - -> [!CAUTION] The `state` data type must support copy semantics on assignment. -> It is possible to pass a `ref` to `state` and/or data structures that include -> `ref`s, but **you must guarantee they remain valid**, either by allocating -> shared memeory, or (preferably) keeping alive a reference to them that the GC -> is aware of, either on the thread where they were initialized or by -> explicitly telling the GC about the cross-thread reference *(TODO: how?)*. +> [!CAUTION] +> Custom state is currently copied by assignment when an appender is cloned. +> Ordinary ORC `ref` values, including references nested in value types, must +> not be shared this way across threads. Keeping an original reference alive +> does not protect reference counts. A safe custom-state and captured-formatter +> ownership API is still pending; use independently owned values or an explicit +> shared-state abstraction with a synchronized lifetime and access protocol. See [testutil][] and the unit tests in [namespaced\_logging][nsl-unit-tests] -for an example. +for a single-threaded example; the test collector's lock does not make its +reference-counted state safe to share across threads. ## Notes on Use in Multi-Threaded Applications -The loggers and appenders in this library are thread-safe and are intended to -behave more intuitively in a multi-threaded environment than -[std/logging][std-logging] while presenting a similar API. This is particularly -true in environments where the logging setup code may be separated from the -thread-management code (in an HTTP server, for example). +This library is intended to support thread-safe logging in multi-threaded +applications, and hopefully to behave more intuitively in a multi-threaded +environment than [std/logging][std-logging] while presenting a similar API. A +key difference is that logging setup can happen separately from thread +creation, such as when an HTTP server manages its own worker threads. The *LogService* object is the main entry point for the logging system and -should be initialized on the main thread. The *LogService* contains a reference -to the "source of truth" for logging configuration and is safe to be shared -between all threads. +should be initialized via *initLogService* during application setup, usually on +the main thread. Pass a copy of that *LogService* to each worker that needs +logging. Such copies use the same logging configuration and will be updated +when there are changes (e.g. to appenders or logging thresholds). Calling +*initLogService* again creates a separate, independent configuration. -The thread which initializes a *LogService* must also be the longest-living -thread that uses that *LogService* instance. If the initializing thread -terminates or the *LogService* object in that thread goes out of scope while -other threads are still running and using the *LogService*, the global state -may be harvested by the garbage collector, leading to use-after-free errors -when other threads attempt to log (likely causing segfaults). +Within each thread, call *threadLocalRef* to obtain a *ThreadLocalLogService*, +then use its *getLogger* method to create loggers. Keep those local services and +loggers within the thread that created them. If the main thread also logs, +create a local service and loggers there too. Appenders configured during setup +are available to each thread without repeating that setup in every worker. -Individual threads should use the *threadLocalRef* proc to obtain a -*ThreadLocalLogService* reference that can be used to create *Logger* objects. -*ThreadLocalLogService* objects cache the global *LogService* state locally to -avoid expensive locks on the shared state. Instead an atomic configuration -version number is maintained to allow the thread-local state to detect global -configuration changes via an inexpensive [load][atomic-load] call and -automatically synchronize only when necessary. +Once workers have their own copies of the *LogService*, the original service +can go out of scope and the thread that initialized it can finish. Logging +remains available while any service copy, local service, or logger using that +service remains alive. Join worker threads before exiting the application so +they have an opportunity to finish logging. -This thread-local caching mechanism is the primary advantage of this logging -system over std/logging in a multi-threaded environment as it means that -the logging system itself is responsible for making sure appenders are -configured for every thread where loggers are used, even if the thread -initialization context is separated from the logging setup code. +You can change logging configuration through a service copy or a local service +in any thread. Those changes are intended to take effect automatically on +subsequent logging calls in every thread using that service, without recreating +loggers or configuring each worker separately. + +> [!NOTE] +> Thread-safety work is still in progress. For now, use the built-in appenders +> with default or stateless formatters when sharing a service across threads. +> Custom appenders with shared reference-based state and formatters with +> captured state are not yet generally safe. Runtime configuration refresh +> and delivery of queued background output at application exit also have known +> failures. See [the regression tests](tests/README.md) for the remaining work. ## Architectural Design @@ -261,18 +266,17 @@ usability in multithreaded environments. The design centers on two key types: #### LogService (Value Type) ```nim type LogService* = object - configVersion: int global: GlobalLogService - appenders: seq[LogAppender] - thresholds: TableRef[string, Level] ``` The *LogService* object is intended to support uses cases such as: - **Main thread initialization**: a mutable *LogService* supports all of the configuration functions you would typically need when initializing logging for an application on the main thread. -- **Cross-thread communication**: Being an `object` type, *LogService* follows - value semantics and can be safely copied between threads. +- **Cross-thread communication**: Copies of a *LogService* can be passed + between threads while keeping the shared configuration alive. Configuration + changes are intended to become visible to each associated + *ThreadLocalLogService* automatically on subsequent logging calls. - **Service composition**: independently initialized *LogService* objects are truly independent and multiple can be created and embedded in larger application contexts. @@ -283,15 +287,32 @@ The *LogService* object is intended to support uses cases such as: #### ThreadLocalLogService (Reference Type) ```nim -type ThreadLocalLogService* = ref LogService +type ThreadLocalLogService* = ref object + shared: LogService + configVersion: int + appenders: seq[LogAppender] + thresholds: TableRef[string, Level] ``` -*ThreadLocalLogService* is a reference to a thread-local copy of a *LogService* -and can be obtained via *threadLocalRef*. We purposefully use reference +*threadLocalRef* builds a fresh *ThreadLocalLogService* cache in the calling +thread, even when the configuration has not changed. We use reference semantics within the context of a thread so that *Logger* objects created within the same thread context share the same *ThreadLocalLogService* reference, avoiding the need to synchronize every *Logger* individually. +*ThreadLocalLogService* is no longer an alias for `ref LogService`. To obtain a +shared handle from a local service, use `local.service` instead of `local[]`: + +```nim +let handle = localLogSvc.service +# Pass handle to a worker, which calls handle.threadLocalRef() itself. +``` + +Configuration methods remain available on both types. Shared handles contain no +cache; `ensureFreshness(handle)` only validates initialization, and +`handle.appenders()` clones the current shared configuration. Local services +retain their per-thread caches and refresh them through `ensureFreshness(local)`. + *ThreadLocalLogService* is the object that users are expected to interact with during regular operation and support both the configuration functions of *LogService* and the creation of *Logger* objects. @@ -302,30 +323,32 @@ during regular operation and support both the configuration functions of #### GlobalLogService (Internal) -Under the hood *LogService* holds a reference to a *GlobalLogService*, a -heap-allocated object that serves as the single source of truth for logging +Under the hood *LogService* holds a pointer to a manually allocated shared +control block that serves as the single source of truth for logging configuration. This internal type is not exposed to library users but manages: - **Shared configuration state**: Appenders, thresholds, and root logging level - **Synchronization primitives**: Locks and atomic variables for thread coordination -- **Background I/O threads**: Dedicated writer threads for console and file - output +- **Ownership**: Atomic retain/release and explicit destruction of configuration - **Configuration versioning**: Atomic version numbers for efficient change detection -The `GlobalLogService` ensures that configuration changes are safely propagated -across all threads while maintaining high performance for logging operations. +Console and file writers remain process-wide. The shared control block owns +appender prototypes; refresh borrows them under the configuration lock and calls +`clone()` to create local instances. Clones must not retain ordinary managed +references shared across threads. That custom-state and formatter contract is +the next part of the ownership work. ### Thread Safety Model #### Safe Cross-Thread Pattern ```nim # Main thread setup -let logService = initLogService() +var logService = initLogService() logService.addAppender(initConsoleLogAppender()) -# Safe: value semantics allow crossing thread boundaries +# Each copy retains the shared control block atomically. proc workerThread(ls: LogService) {.thread.} = # Convert to thread-local reference for efficient operations let tlls = threadLocalRef(ls) @@ -351,7 +374,7 @@ The library uses atomic version numbers to efficiently detect configuration changes: ```nim -proc ensureFreshness*(ls: var LogService) = +proc ensureFreshness*(ls: ThreadLocalLogService) = # Cheap atomic check first if ls.configVersion == ls.global.configVersion.load(): return # No changes, return immediately diff --git a/src/namespaced_logging.nim b/src/namespaced_logging.nim index c2bc205..e500492 100644 --- a/src/namespaced_logging.nim +++ b/src/namespaced_logging.nim @@ -7,19 +7,19 @@ from std/logging import Level export Level type - GlobalLogServiceObj {.acyclic.} = object + GlobalLogServiceObj = object + owners: Atomic[int] # Lifetime of independently owned service handles configVersion: Atomic[int] # To signal the need for threads to update - initialized: Atomic[bool] # To protect deconstruction lock: Lock # To protect reads/writes across threads appenders: seq[LogAppender] - thresholds: TableRef[string, Level] + thresholds: Table[string, Level] rootLevel: Atomic[Level] errorHandler: ErrorHandlerFunc errorHandlerLock: Lock - GlobalLogService = ref GlobalLogServiceObj + GlobalLogService = ptr GlobalLogServiceObj ErrorHandlerFunc* = @@ -27,27 +27,32 @@ type LogService* = object - ## Thread-local logging state intended for use by library consumers - configVersion: int # Version of the global state we have - global: GlobalLogService # Reference to the global state + ## Copyable shared configuration handle with an atomic lifetime. + ## Each thread must own its own handle; do not concurrently assign to or + ## destroy the same handle variable while another thread reads it. + global: GlobalLogService - appenders: seq[LogAppender] # Thread-local copy of appenders + + ThreadLocalLogService* = ref object + ## Cache confined to the thread that creates it. Appender clones must + ## themselves respect thread ownership of custom state and formatters. + shared: LogService + configVersion: int + appenders: seq[LogAppender] thresholds: TableRef[string, Level] - ThreadLocalLogService* = ref LogService - - Logger* = ref object scope*: string threadSvc: ThreadLocalLogService LogAppender* = ref object of RootObj - ## Base type for log appenders. Note that all LogAppenders must (and do) - ## have a clone method that makes a thread-safe copy of the appender state - ## that is used when adding appenders to the global service state as well - ## as during individual thread state refresh. + ## Base type for log appenders. Note that all LogAppenders must have a + ## clone method which must return an independently owned appender for + ## shared configuration and for each thread's cache. Nested state and + ## formatter references also need safe ownership; allocating a new outer + ## appender alone does not make shared ORC references safe. namespace*: string ## Allows filtering of messages based on their scope. Messages are @@ -128,6 +133,54 @@ type const UninitializedConfigVersion = low(int) +proc retainGlobal(gls: GlobalLogService) {.inline.} = + if gls != nil: + discard gls.owners.fetchAdd(1, moRelaxed) + + +proc releaseGlobal(gls: GlobalLogService) = + if gls != nil and gls.owners.fetchSub(1, moAcquireRelease) == 1: + # The last owner has exclusive access to the control block. Its managed + # fields must be destroyed explicitly because it is manually allocated. + `=destroy`(gls.appenders) + `=destroy`(gls.thresholds) + deinitLock(gls.errorHandlerLock) + deinitLock(gls.lock) + deallocShared(gls) + + +proc `=destroy`*(ls: LogService) = + releaseGlobal(ls.global) + + +proc `=copy`*(dest: var LogService, source: LogService) = + if dest.global == source.global: return + retainGlobal(source.global) + releaseGlobal(dest.global) + dest.global = source.global + + +proc `=dup`*(source: LogService): LogService = + retainGlobal(source.global) + result.global = source.global + + +proc `=wasMoved`*(ls: var LogService) = + ls.global = nil + + +# The compiler-generated sink operation transfers the pointer after releasing +# the destination. It does not retain the transferred owner. +template global(ls: ThreadLocalLogService): untyped = + ls.shared.global + + +proc service*(ls: ThreadLocalLogService): LogService = + ## Obtain an independently owned shared handle, e.g. to pass to a worker. + ## This replaces copying ls[] when ThreadLocalLogService was ref LogService. + ls.shared + + var consoleLogging {.global.}: LogWriterThreadState[ConsoleMessage] var fileLogging {.global.}: LogWriterThreadState[FileMessage] var loggingThreadInitLock {.global.}: Lock @@ -218,88 +271,79 @@ proc shutdownThreadedFileLogging() = fileLogging.initialized.store(false) -proc `=destroy`*(gls: var GlobalLogServiceObj) = - # only one thread should cleanup - if not gls.initialized.exchange(false): return - - try: deinitLock(gls.lock) - except Exception: discard - - try: deinitLock(gls.errorHandlerLock) - except Exception: discard - - proc ensureFreshness*(ls: var LogService) = + ## A shared handle has no cached configuration. Retained for callers that + ## previously refreshed LogService values; only local services need refresh. + if ls.global == nil: + raise newException(ValueError, + "LogService not properly initialized. Use initLogService") + + +proc ensureFreshness*(ls: ThreadLocalLogService) = ## Check our thread-local version of the logging service configuration ## against the global log service definition. This uses an atomic version ## number to allow the check to be inexpensive, only incurring the more ## expensive copy operations if there are actual changes. - if ls.global.isNil or not ls.global.initialized.load(): + if ls.isNil or ls.global.isNil: raise newException(ValueError, "LogService not properly initialized. Use initLogService to obtain a" & "properly initialized LogService object") - if ls.configVersion == ls.global.configVersion.load(): return + # Keep a stable borrowed pointer while inspecting configuration. In + # particular, do not iterate a seq through a function-returned expression: + # that can create an owning temporary and register its shared appender refs + # with this thread's ORC cycle collector even while the lock is held. + let gls = ls.shared.global + if ls.configVersion == gls.configVersion.load(): return - withLock ls.global.lock: - ls.configVersion = ls.global.configVersion.load + withLock gls.lock: + ls.configVersion = gls.configVersion.load ls.appenders = @[] - for a in ls.global.appenders: ls.appenders.add(clone(a)) + for a in gls.appenders: ls.appenders.add(clone(a)) ls.thresholds = newTable[string, Level]() - for ns, t in pairs(ls.global.thresholds): ls.thresholds[ns] = t - - -proc ensureFreshness*(ls: ThreadLocalLogService) = ensureFreshness(ls[]) + for ns, t in pairs(gls.thresholds): ls.thresholds[ns] = t proc initGlobalLogService( rootLevel = lvlAll, errorHandler = defaultErrorHandlerFunc): GlobalLogService = - result = GlobalLogService() + result = cast[GlobalLogService](allocShared0(sizeof(GlobalLogServiceObj))) + result.owners.store(1) result.configVersion.store(0) initLock(result.lock) initLock(result.errorHandlerLock) result.appenders = @[] - result.thresholds = newTable[string, Level]() + result.thresholds = initTable[string, Level]() result.rootLevel.store(rootLevel) result.errorHandler = errorHandler - result.initialized.store(true) - -proc initLogService(gls: GlobalLogService): LogService = - var lsRef: ThreadLocalLogService = ThreadLocalLogService( - configVersion: UninitializedConfigVersion, global: gls) - ensureFreshness(lsRef) - result = lsRef[] - proc initLogService*( rootLevel = lvlAll, errorHandler = defaultErrorHandlerFunc): LogService = - ## Initialize a new LogService instance. The resulting LogService object can - ## be safely copied between threads and provides thread-safe synchronization - ## of logger configuration and shared state. It is important that the - ## LogService object returned is retained by the main thread so that garbage - ## collection does not harvest the global state while it is still in use on - ## other threads. + ## Initialize an independently owned shared configuration handle. Copies + ## retain the shared control block atomically, including copies in worker + ## arguments and local services. The original handle need not outlive them. + ## The resulting *LogService* object can be safely passed between threads to + ## initialize *ThreadLocalLogService* objects but note that thread-safe use + ## still requires that appenders and formatters satisfy the ownership + ## requirements documented on *LogAppender.* ## ## Multiple calls to *initLogService* will result in completely independent - ## *LogService* objects with their own synchronized coniguration and global - ## state. This is not expected to be a common usage, but it is supported. - ## object used to actually configure the log service, attach appenders, - ## configure thresholds, and create loggers. The ref returned by this - ## procedure should also be retained by the main thread so that garbage - ## collection does not harvest the global state while it is still in use. - let global = initGlobalLogService(rootLevel, errorHandler) - result = initLogService(global) + ## *LogService* objects with their own synchronized configuration and global + ## state. + result.global = initGlobalLogService(rootLevel, errorHandler) proc threadLocalRef*(ls: LogService): ThreadLocalLogService = - new result - result[] = ls + ## Build a fresh cache in the calling thread, retaining only the shared + ## handle. Never copy another thread's cached appender or threshold refs. + result = ThreadLocalLogService(shared: ls, + configVersion: UninitializedConfigVersion) + ensureFreshness(result) proc reportLoggingError( @@ -361,7 +405,7 @@ proc setErrorHandler*( proc setErrorHandler*( ls: ThreadLocalLogService, errHandler = defaultErrorHandlerFunc) {.gcsafe.} = - setErrorHandler(ls[], errHandler) + setErrorHandler(ls.shared, errHandler) proc setRootThreshold*(ls: var LogService, lvl: Level) {.gcsafe.} = @@ -370,7 +414,7 @@ proc setRootThreshold*(ls: var LogService, lvl: Level) {.gcsafe.} = proc setRootThreshold*(ls: ThreadLocalLogService, lvl: Level) {.gcsafe.} = - setRootThreshold(ls[], lvl) + setRootThreshold(ls.shared, lvl) func formatSimpleTextLog*(msg: LogMessage): string {.gcsafe.} = msg.msg @@ -384,11 +428,10 @@ proc setThreshold*(ls: var LogService, scope: string, lvl: Level) {.gcsafe.} = ls.global.thresholds[scope] = lvl ls.global.configVersion.atomicInc - ensureFreshness(ls) - proc setThreshold*(ls: ThreadLocalLogService, scope: string, lvl: Level) {.gcsafe.} = - setThreshold(ls[], scope, lvl) + setThreshold(ls.shared, scope, lvl) + ensureFreshness(ls) proc setThresholds*(ls: var LogService, thresholds: TableRef[string, Level]) {.gcsafe.} = @@ -396,11 +439,10 @@ proc setThresholds*(ls: var LogService, thresholds: TableRef[string, Level]) {.g for k,v in thresholds: ls.global.thresholds[k] = v ls.global.configVersion.atomicInc - ensureFreshness(ls) - proc setThresholds*(ls: ThreadLocalLogService, thresholds: TableRef[string, Level]) {.gcsafe.} = - setThresholds(ls[], thresholds) + setThresholds(ls.shared, thresholds) + ensureFreshness(ls) proc getLogger*( ls: ThreadLocalLogService, @@ -437,38 +479,36 @@ proc getLogger*( proc appenders*(ls: var LogService): seq[LogAppender] {.gcsafe.} = - for a in ls.appenders: result.add(clone(a)) + withLock ls.global.lock: + for a in ls.global.appenders: result.add(clone(a)) proc appenders*(ls: ThreadLocalLogService): seq[LogAppender] {.gcsafe.} = - ls[].appenders() + for a in ls.appenders: result.add(clone(a)) proc addAppender*(ls: var LogService, appender: LogAppender) {.gcsafe.} = - ## Add a log appender to the global log service and refresh the local thread - ## state. The updated global state will trigger other threads to refresh - ## their state as well. + ## Add a log appender to the shared configuration. Local services refresh + ## their cached state on their next freshness check. withLock ls.global.lock: var copiedAppender = clone(appender) ls.global.appenders.add(copiedAppender) ls.global.configVersion.atomicInc + +proc addAppender*(ls: ThreadLocalLogService, appender: LogAppender) {.gcsafe.} = + addAppender(ls.shared, appender) ensureFreshness(ls) -proc addAppender*(ls: ThreadLocalLogService, appender: LogAppender) {.gcsafe.} = - addAppender(ls[], appender) - - proc clearAppenders*(ls: var LogService) {.gcsafe.} = - ## Remove all log appenders added to the global log service and refresh the - ## local thread state. The updated global state will trigger other threads to - ## refresh their state as well. + ## Remove all shared appenders. Local services refresh their cached state + ## on their next freshness check. withLock ls.global.lock: ls.global.appenders = @[] ls.global.configVersion.atomicInc proc clearAppenders*(ls: ThreadLocalLogService) {.gcsafe.} = - clearAppenders(ls[]) + clearAppenders(ls.shared) func getEffectiveThreshold(logger: Logger): Level {.gcsafe.} = @@ -729,7 +769,7 @@ method clone*(cla: ConsoleLogAppender): LogAppender {.gcsafe.} = proc appendLogMessageMultiThreaded( cla: ConsoleLogAppender, - ls: ref LogService, + ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = if not consoleLogging.initialized.load(): @@ -758,7 +798,7 @@ proc appendLogMessageMultiThreaded( proc appendLogMessageSingleThreaded( cla: ConsoleLogAppender, - ls: ref LogService, + ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: @@ -814,7 +854,7 @@ method clone*(fla: FileLogAppender): LogAppender {.gcsafe.} = proc appendLogMessageMultiThreaded( fla: FileLogAppender, - ls: ref LogService, + ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = if not fileLogging.initialized.load(): @@ -829,7 +869,7 @@ proc appendLogMessageMultiThreaded( proc appendLogMessageSingleThreaded( fla: FileLogAppender, - ls: ref LogService, + ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: @@ -922,18 +962,34 @@ when isMainModule: test "initLogService creates valid service": let ls = initLogService() + let local = ls.threadLocalRef() check: ls.global != nil - ls.global.initialized.load() == true + ls.global.owners.load() == 2 ls.global.configVersion.load() == 0 ls.global.rootLevel.load() == lvlAll - ls.configVersion >= 0 - ls.configVersion == ls.global.configVersion.load + local.configVersion >= 0 + local.configVersion == ls.global.configVersion.load test "initLogService with custom root level": let ls = initLogService(lvlInfo) check ls.global.rootLevel.load() == lvlInfo + test "threadLocalRef builds independent caches for an unchanged service": + var service = initLogService() + service.addAppender(initConsoleLogAppender()) + service.setThreshold("worker", lvlInfo) + let first = service.threadLocalRef() + let second = service.threadLocalRef() + check: + first.global == second.global + first.configVersion == second.configVersion + cast[pointer](first.thresholds) != cast[pointer](second.thresholds) + first.thresholds["worker"] == second.thresholds["worker"] + first.appenders.len == 1 + second.appenders.len == 1 + first.appenders[0] != second.appenders[0] + suite "LogService Configuration": setup: let ls = threadLocalRef(initLogService()) @@ -961,7 +1017,7 @@ when isMainModule: check ls.thresholds["test"] == lvlError test "ensureFreshness syncs configuration between multiple loggers": - var ls2 = ls[] # use copy semantics + let ls2 = ls.service.threadLocalRef() ls.setThreshold("api", lvlWarn) check: @@ -992,7 +1048,7 @@ when isMainModule: initCond(cUpd) proc runA(lsGiven: LogService) {.thread, gcsafe.} = - var ls = lsGiven + let ls = lsGiven.threadLocalRef() withLock lock: # 1a. Initialize both threads cInitA.signal() @@ -1003,7 +1059,7 @@ when isMainModule: cUpd.signal() proc runB(lsGiven: LogService) {.thread, gcsafe.} = - var ls = lsGiven + let ls = lsGiven.threadLocalRef() withLock lock: # 1b. Initialize both threads cInitB.signal() @@ -1016,10 +1072,10 @@ when isMainModule: check ls.thresholds["api"] == lvlWarn # 1. Initialize both threads - createThread(tA, runA, ls[]) + createThread(tA, runA, ls.service) withLock lock: wait(cInitA, lock) - createThread(tB, runB, ls[]) + createThread(tB, runB, ls.service) withLock lock: wait(cInitB, lock) cInitAll.broadcast() # finished with initialization diff --git a/tests/README.md b/tests/README.md index 04da232..c9b897d 100644 --- a/tests/README.md +++ b/tests/README.md @@ -9,8 +9,8 @@ Run from the repository root: | --- | --- | | `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 testRegression` | Handle lifetime, configuration freshness, refresh failure recovery, appender-state cleanup, and writer shutdown | +| `nimble testThreadSafety` | Separate ThreadSanitizer processes for service ownership, last-owner teardown, reconfiguration, 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. @@ -23,8 +23,8 @@ 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. +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: @@ -33,14 +33,22 @@ TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s tests/bin/thread_safety ser ``` The worker start barrier ensures argument setup finishes before the concurrent -operations begin. Parent owners survive until all workers join. Custom-state +operations begin. In `service-lifetime`, workers first acquire local services; +the parent then releases the original handle before allowing them to proceed. +Thread arguments contain borrowed pointers so no hidden owning argument keeps +the service alive. Atomic construction/destruction counters verify that every +tracked appender is released exactly once after the workers join. +`service-reconfigure` exercises concurrent updates and local cache refresh. +The other scenarios retain parent owners 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 +The in-process regression tests are deterministic. The lifetime suite checks +copying, self-assignment, replacement, moving, container copies, and exporting a +handle from a local service. 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, @@ -51,3 +59,8 @@ 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. + +After the shared-handle implementation, the service sanitizer scenarios, lifetime +suite, and appender-state cleanup regression should pass. The custom-state and +formatter sanitizer cases, `isEnabled` freshness, failed-refresh recovery, and +writer shutdown remain failing regressions for subsequent work. diff --git a/tests/regressions.nim b/tests/regressions.nim index c567f5e..1914ffe 100644 --- a/tests/regressions.nim +++ b/tests/regressions.nim @@ -24,12 +24,78 @@ proc `=destroy`(probe: LifetimeProbeObj) = proc ignoreMessage(state: LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} = discard -proc createAndReleaseService(destroyed: ptr int) = - var service = initLogService() - service.addAppender(initCustomLogAppender( +proc watchedService(destroyed: ptr int): LogService = + result = initLogService() + result.addAppender(initCustomLogAppender( LifetimeProbe(destroyed: destroyed), ignoreMessage)) + +proc createAndReleaseService(destroyed: ptr int) = + var service = watchedService(destroyed) + service.setThreshold("worker", lvlInfo) # All owning handles leave scope here. No thread or cycle is involved. +suite "ORC service handle lifetime": + test "copy, self-assignment, replacement, and move retain exactly one lifetime": + var firstDestroyed, replacedDestroyed = 0 + block: + var first = watchedService(addr firstDestroyed) + var other = watchedService(addr replacedDestroyed) + other = first + check replacedDestroyed == 1 + first = first + first = LogService() + check firstDestroyed == 0 + + var moved = move(other) + expect ValueError: + discard other.threadLocalRef() + moved.setThreshold("worker", lvlInfo) + let local = moved.threadLocalRef() + moved = LogService() + check firstDestroyed == 0 + check local.getLogger("worker").isEnabled(lvlInfo) + check firstDestroyed == 1 + check replacedDestroyed == 1 + + test "handles embedded in copied containers retain the service": + var destroyed = 0 + block: + var source = watchedService(addr destroyed) + var handles = @[source, source] + var copied = handles + source = LogService() + handles.setLen(0) + check destroyed == 0 + copied[0].setThreshold("worker", lvlWarn) + let local = copied[1].threadLocalRef() + check not local.getLogger("worker").isEnabled(lvlInfo) + copied.setLen(0) + check destroyed == 0 + check destroyed == 1 + + test "an exported handle outlives the local service it came from": + var destroyed = 0 + block: + var exported: LogService + block: + let local = watchedService(addr destroyed).threadLocalRef() + exported = local.service + check destroyed == 0 + check exported.threadLocalRef().getLogger("worker").isEnabled(lvlInfo) + check destroyed == 1 + + test "failed local construction releases its shared owner and partial cache": + var destroyed = 0 + var control: CloneControl + block: + var service = watchedService(addr destroyed) + service.addAppender(FallibleAppender(control: addr control)) + control.failNext = true + expect ValueError: + discard service.threadLocalRef() + check destroyed == 0 + check destroyed == 1 + suite "ORC ownership and configuration regressions": test "isEnabled observes a namespace change before any log call": var service = initLogService() diff --git a/tests/run_tsan.sh b/tests/run_tsan.sh index a49ee5f..d6251dd 100644 --- a/tests/run_tsan.sh +++ b/tests/run_tsan.sh @@ -3,7 +3,7 @@ set -u binary=${1:?Expected the ThreadSanitizer test executable} result=0 -for scenario in independent service custom-state formatter; do +for scenario in independent service service-lifetime service-reconfigure 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" diff --git a/tests/thread_safety.nim b/tests/thread_safety.nim index d5e449b..c6a4bea 100644 --- a/tests/thread_safety.nim +++ b/tests/thread_safety.nim @@ -6,6 +6,7 @@ import ../src/namespaced_logging const iterations = 1_000 var start: Atomic[bool] var cloneLock: Lock +var ready: Atomic[int] proc awaitStart() = while not start.load(): @@ -27,6 +28,50 @@ proc independentWorker() {.thread.} = let logger = local.getLogger("worker") doAssert logger.isEnabled(lvlInfo) +type + AppenderLifetimes = object + created, destroyed: Atomic[int] + TrackedAppenderObj = object of LogAppender + lifetimes: ptr AppenderLifetimes + TrackedAppender = ref TrackedAppenderObj + +proc `=destroy`(app: TrackedAppenderObj) = + if app.lifetimes != nil: + app.lifetimes.destroyed.atomicInc() + `=destroy`(app.namespace) + +proc trackedAppender(lifetimes: ptr AppenderLifetimes): TrackedAppender = + lifetimes.created.atomicInc() + TrackedAppender(lifetimes: lifetimes) + +method clone(app: TrackedAppender): LogAppender {.gcsafe.} = + trackedAppender(app.lifetimes) + +proc lifetimeWorker(source: ptr LogService) {.thread.} = + # Borrow the original only until this thread owns a local service. The + # readiness barrier lets the parent release it before we continue. + let local = source[].threadLocalRef() + ready.atomicInc() + awaitStart() + for i in 0 ..< iterations: + var handle = local.service + var copied = handle + handle = LogService() + var moved = move(copied) + moved.setThreshold("worker", lvlInfo) + let nested = moved.threadLocalRef() + doAssert nested.getLogger("worker").isEnabled(lvlInfo) + # Local caches and the last shared owner are destroyed on worker threads. + +proc reconfigureWorker(service: LogService) {.thread.} = + var handle = service + let local = service.threadLocalRef() + awaitStart() + for i in 0 ..< iterations: + handle.setThreshold("worker", lvlInfo) + local.ensureFreshness() + doAssert local.getLogger("worker").isEnabled(lvlInfo) + type CustomState = ref object value: int @@ -86,6 +131,32 @@ proc main() = createThread(workers[i], stateWorker, addr source) start.store(true) joinThreads(workers) + of "service-lifetime": + var lifetimes: AppenderLifetimes + var service = initLogService() + block: + let original = trackedAppender(addr lifetimes) + service.addAppender(original) + var workers: array[4, Thread[ptr LogService]] + for i in 0 ..< workers.len: + createThread(workers[i], lifetimeWorker, addr service) + while ready.load() != workers.len: + discard + # Thread arguments contain only a borrowed pointer, so there are no hidden + # owning handles in Thread.data keeping the control block alive here. + service = LogService() + start.store(true) + joinThreads(workers) + doAssert lifetimes.created.load() > workers.len + doAssert lifetimes.destroyed.load() == lifetimes.created.load() + of "service-reconfigure": + var service = initLogService() + service.addAppender(initConsoleLogAppender()) + var workers: array[4, Thread[LogService]] + for i in 0 ..< workers.len: + createThread(workers[i], reconfigureWorker, service) + start.store(true) + joinThreads(workers) of "formatter": var source = initConsoleLogAppender() source.formatter = makeFormatter("prefix: ")