Separate shared service ownership from thread-local logging caches

This commit is contained in:
jdb committed 2026-09-22 07:18:22 -05:00
1 parent c1c8a3c072
commit 761bd66793
6 files changed
+386 -157

No files matched your search

+19 -6
View File
@@ -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.
+69 -3
View File
@@ -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()
+1 -1
View File
@@ -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"
+71
View File
@@ -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: ")