Define explicit ownership for custom appenders and formatters

Add SharedLogState for synchronized value data and factories for
independently owned appender state and captured formatter closures.
Reject unsafe configuration state, update the test collector to value
snapshots, and document the breaking APIs in version 3.0.0.

Expand ORC ownership and sanitizer coverage and reject stale test
executables.
This commit is contained in:
jdb committed 2026-09-28 14:28:24 -05:00
1 parent 851caef706
commit b2d0e9dade
11 files changed
+808 -110

No files matched your search

+50 -12
View File
@@ -9,12 +9,15 @@ 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` | 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 testRegression` | Custom-state/formatter ownership, 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, shared state, factory state, formatter closures, collector snapshots, timestamps, and the Nim allocator, 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.
Old executables are removed before compilation, and a new executable must exist
before a suite runs. This prevents stale binaries from hiding compilation errors
when a nested Nimble command fails to propagate its exit status.
Executables are generated in ignored `tests/bin/`. The shutdown child is built
with `-d:multithreaded`; `--threads:on` alone does not enable background writers.
@@ -39,13 +42,43 @@ 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
`shared-state-lifetime` drops the original state handle before concurrent
mutations and verifies one final destruction with all updates present.
`formatter-lifetime` drops an already-used original formatter and checks both
independent closure counters and exact cleanup on worker threads. `factory-state`
uses per-thread cyclic reference graphs, explicitly runs the ORC collector, and
checks that each worker maintains its own counter. `collector` concurrently
records messages containing JSON and exceptions and mutates returned snapshots.
These ownership scenarios use explicit timestamps where messages are needed.
The separate `timestamp` case exercises concurrent `initLogMessage()` calls. It
currently exposes a sanitizer report in libc local-time conversion reached via
Nim's `std/times.now()`; this remains a separate thread-safety issue.
`allocator` calls the standalone reproduction in `runtime_allocator.nim`, which
imports no logging code. It exercises sequence growth and clearing under a lock
alongside thread-local closure allocations. On Nim 2.2.10 it reproduces a report
in `system/alloc.nim`'s `compensateCounters` / shared-free-list path. The same
runtime report can occur in `factory-state` and other allocation-heavy cases.
The ten ownership scenarios passed debug and release diagnostic builds with
`-d:useMalloc`;
`nimble test` deliberately retains the default allocator and exposes these
reports rather than suppressing them.
The original custom-state and formatter scenarios retain parent owners until all
workers join. They 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.
`ownership.nim`, imported by `regressions.nim`, checks independent snapshots,
exception recovery, factory and clone behavior, and the built-in formatter paths.
Compile-time checks reject direct and nested refs, captured formatter arguments,
and embedded synchronization primitives. The formerly unsafe custom-state and
formatter scenarios now exercise the supported shared-handle and factory APIs;
the unsafe forms are tested as compilation failures.
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
@@ -55,12 +88,17 @@ 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.
This suite does not yet force an active producer/channel-close race or exhaust
ORC cycle-collector interleavings. It provides targeted regressions for ownership,
configuration, cleanup, timestamps, allocator behavior, and shutdown.
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.
The ownership scenarios, lifetime suite, and appender-state cleanup regression
exercise the new ownership contracts. `isEnabled` freshness, failed-refresh
recovery, local-time timestamp construction, allocator reports, and writer
shutdown remain for subsequent work.
The standalone `ownership.nim` regression suite passed AddressSanitizer and
LeakSanitizer with `--mm:orc -d:useMalloc`. An additional worker-thread build found
no invalid accesses in the shared-state, factory-state, formatter-lifetime, and collector
scenarios. LeakSanitizer reported per-thread ORC cycle-registration buffers
allocated by the Nim runtime; this is not a clean leak-check result.
+170
View File
@@ -0,0 +1,170 @@
import std/[atomics, locks, options, tables, unittest]
import ../src/namespaced_logging
type
UnsafeState = ref object
value: int
NestedUnsafeState = object
values: seq[UnsafeState]
VariantUnsafeState = object
case hasReference: bool
of true: reference: UnsafeState
of false: value: int
EmbeddedLock = object
lock: Lock
Slot = enum firstSlot, secondSlot
proc unsafeCallback(state: var UnsafeState, msg: LogMessage) {.gcsafe, noconv.} = discard
proc nestedCallback(state: var NestedUnsafeState, msg: LogMessage) {.gcsafe, noconv.} = discard
proc makePrefix(prefix: string): StatefulLogFormatterFunc =
result = proc(msg: LogMessage): string {.gcsafe.} = prefix & msg.msg
static:
doAssert not compiles(initSharedLogState(UnsafeState()))
doAssert not compiles(initSharedLogState(NestedUnsafeState()))
doAssert not compiles(initSharedLogState(VariantUnsafeState()))
doAssert not compiles(initSharedLogState(some(UnsafeState())))
doAssert not compiles(initCustomLogAppender(UnsafeState(), unsafeCallback))
doAssert not compiles(initCustomLogAppender(NestedUnsafeState(), nestedCallback))
doAssert not compiles(initConsoleLogAppender(formatter = makePrefix("unsafe")))
doAssert not compiles(initSharedLogState(makePrefix("unsafe")))
doAssert not compiles(initSharedLogState(default(Lock)))
doAssert not compiles(initSharedLogState(default(Atomic[int])))
doAssert not compiles(initSharedLogState(default(EmbeddedLock)))
doAssert compiles(initSharedLogState(default(array[Slot, string])))
doAssert compiles(initSharedLogState(initTable[string, seq[string]]()))
proc counterFormatter(prefix: string): StatefulLogFormatterFunc =
var count = 0
result = proc(msg: LogMessage): string {.gcsafe.} =
inc count
prefix & $count & ": " & msg.msg
type
ValueCounter = object
count: int
output: SharedLogState[seq[int]]
LocalCounter = ref object
count: int
output: SharedLogState[seq[int]]
proc initCounter(output: SharedLogState[seq[int]]): LocalCounter =
LocalCounter(output: output)
proc recordCounter(state: var LocalCounter, msg: LogMessage) {.gcsafe, noconv.} =
inc state.count
let count = state.count
state.output.withState(proc(values: var seq[int]) = values.add(count))
proc recordCounter(state: var ValueCounter, msg: LogMessage) {.gcsafe, noconv.} =
inc state.count
let count = state.count
state.output.withState(proc(values: var seq[int]) = values.add(count))
proc ignoreError(err: ref Exception, msg: string) {.gcsafe, nimcall.} = discard
suite "Custom state and formatter ownership":
test "shared value snapshots are independent and updates are explicit":
let state = initSharedLogState(@[@["original"]])
var first = state.snapshot()
first[0][0] = "changed"
check state.snapshot() == @[@["original"]]
state.withState(proc(value: var seq[seq[string]]) = value[0].add("second"))
check state.snapshot() == @[@["original", "second"]]
test "callback exceptions release the shared state lock":
let state = initSharedLogState(0)
expect ValueError:
state.withState(proc(value: var int) =
inc value
raise newException(ValueError, "injected failure"))
check state.snapshot() == 1
state.withState(proc(value: var int) = inc value)
check state.snapshot() == 2
test "a callback can release its caller's last handle":
var state = initSharedLogState(@["alive"])
state.withState(proc(value: var seq[string]) =
state = default(typeof(state))
value.add("still alive")
check value == @["alive", "still alive"])
expect ValueError: discard state.snapshot()
test "empty and moved handles reject access":
var original = initSharedLogState(42)
let moved = move(original)
check moved.snapshot() == 42
expect ValueError: discard original.snapshot()
expect ValueError: original.withState(proc(value: var int) = discard)
test "appender factories retain local state and reset it on clone":
let output = initSharedLogState(newSeq[int]())
var service = initLogService()
service.addAppender(initFactoryCustomLogAppender(output, initCounter, recordCounter))
let first = service.threadLocalRef().getLogger("first")
let second = service.threadLocalRef().getLogger("second")
first.info("one")
first.info("two")
second.info("one")
check output.snapshot() == @[1, 2, 1]
test "value appender state is mutable and independently copied":
let output = initSharedLogState(newSeq[int]())
var service = initLogService()
service.addAppender(initCustomLogAppender(ValueCounter(output: output), recordCounter))
let first = service.threadLocalRef().getLogger("first")
let second = service.threadLocalRef().getLogger("second")
first.info("one")
first.info("two")
second.info("one")
check output.snapshot() == @[1, 2, 1]
test "a failed appender factory is retried on the next message":
let calls = initSharedLogState(0)
proc factory(calls: SharedLogState[int]): UnsafeState =
calls.withState(proc(count: var int) = inc count)
if calls.snapshot() == 1:
raise newException(ValueError, "injected failure")
UnsafeState()
var service = initLogService(errorHandler = ignoreError)
service.addAppender(initFactoryCustomLogAppender(calls, factory, unsafeCallback))
let logger = service.threadLocalRef().getLogger("worker")
logger.info("first attempt")
logger.info("retry")
logger.info("reuse")
check calls.snapshot() == 2
test "formatter clones create independent captured state":
let original = initLogFormatter("count ", counterFormatter)
let message = LogMessage(msg: "hello")
check original.format(message) == "count 1: hello"
let copied = clone(original)
check original.format(message) == "count 2: hello"
check copied.format(message) == "count 1: hello"
test "every built-in appender clones its formatter configuration":
let formatter = initLogFormatter("count ", counterFormatter)
let message = LogMessage(msg: "hello")
let console = initConsoleLogAppender(formatter)
let file = initFileLogAppender("unused.log", formatter)
let standard = initStdLoggingAppender(formatter = formatter)
check console.formatter.format(message) == "count 1: hello"
check file.formatter.format(message) == "count 1: hello"
check standard.formatter.format(message) == "count 1: hello"
check console.formatter.format(message) == "count 2: hello"
check ConsoleLogAppender(clone(console)).formatter.format(message) == "count 1: hello"
check FileLogAppender(clone(file)).formatter.format(message) == "count 1: hello"
check StdLoggingAppender(clone(standard)).formatter.format(message) == "count 1: hello"
test "a failed formatter factory is retried":
let calls = initSharedLogState(0)
proc factory(calls: SharedLogState[int]): StatefulLogFormatterFunc =
calls.withState(proc(count: var int) = inc count)
if calls.snapshot() == 1:
raise newException(ValueError, "injected failure")
makePrefix("ready: ")
let formatter = initLogFormatter(calls, factory)
expect ValueError: discard formatter.format(LogMessage(msg: "hello"))
check formatter.format(LogMessage(msg: "hello")) == "ready: hello"
check formatter.format(LogMessage(msg: "again")) == "ready: again"
check calls.snapshot() == 2
+6 -4
View File
@@ -1,5 +1,6 @@
import std/[os, osproc, strutils, tempfiles, unittest]
import ../src/namespaced_logging
import ./ownership
type
CloneControl = object
@@ -16,18 +17,19 @@ method clone(app: FallibleAppender): LogAppender {.gcsafe.} =
type
LifetimeProbeObj = object
destroyed: ptr int
LifetimeProbe = ref LifetimeProbeObj
LifetimeProbe = SharedLogState[LifetimeProbeObj]
proc `=destroy`(probe: LifetimeProbeObj) =
inc probe.destroyed[]
if probe.destroyed != nil:
inc probe.destroyed[]
proc ignoreMessage(state: LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} =
proc ignoreMessage(state: var LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} =
discard
proc watchedService(destroyed: ptr int): LogService =
result = initLogService()
result.addAppender(initCustomLogAppender(
LifetimeProbe(destroyed: destroyed), ignoreMessage))
initSharedLogState(LifetimeProbeObj(destroyed: destroyed)), ignoreMessage))
proc createAndReleaseService(destroyed: ptr int) =
var service = watchedService(destroyed)
+1 -1
View File
@@ -3,7 +3,7 @@ set -u
binary=${1:?Expected the ThreadSanitizer test executable}
result=0
for scenario in independent service service-lifetime service-reconfigure custom-state formatter; do
for scenario in independent service service-lifetime service-reconfigure custom-state formatter shared-state-lifetime factory-state collector formatter-lifetime timestamp allocator; do
echo "ThreadSanitizer scenario: $scenario"
if TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s "$binary" "$scenario"; then
echo "PASS: $scenario"
+38
View File
@@ -0,0 +1,38 @@
## Standalone reproduction of Nim 2.2.10's allocator sanitizer report.
## No logging-library imports. All accesses to the shared sequence hold a lock.
import std/[atomics, locks]
type AllocatorData = object
lock: Lock
entries: seq[int]
total: int
var start: Atomic[bool]
proc withData(data: ptr AllocatorData,
action: proc(entries: var seq[int]) {.gcsafe.}) =
withLock data.lock:
action(data.entries)
inc data.total
proc append(data: ptr AllocatorData, value: int) =
data.withData(proc(entries: var seq[int]) =
entries.add(value)
if entries.len >= 64: entries = @[])
proc worker(data: ptr AllocatorData) {.thread.} =
while not start.load(): discard
for i in 0 ..< 10_000: data.append(i)
proc runAllocatorRegression*() =
var data: AllocatorData
initLock(data.lock)
defer: deinitLock(data.lock)
var workers: array[4, Thread[ptr AllocatorData]]
for thread in workers.mitems: createThread(thread, worker, addr data)
start.store(true)
joinThreads(workers)
doAssert data.total == 40_000
when isMainModule:
runAllocatorRegression()
+173 -9
View File
@@ -1,9 +1,12 @@
## 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 std/[atomics, json, locks, options, os, times]
import ../src/namespaced_logging
import ../src/namespaced_logging/testutil
import ./runtime_allocator
const iterations = 1_000
const collectorIterations = 100
var start: Atomic[bool]
var cloneLock: Lock
var ready: Atomic[int]
@@ -73,11 +76,11 @@ proc reconfigureWorker(service: LogService) {.thread.} =
doAssert local.getLogger("worker").isEnabled(lvlInfo)
type
CustomState = ref object
CustomState = object
value: int
StatefulAppender = CustomLogAppender[CustomState]
StatefulAppender = CustomLogAppender[SharedLogState[CustomState]]
proc ignoreMessage(state: CustomState, msg: LogMessage) {.gcsafe, noconv.} =
proc ignoreMessage(state: var SharedLogState[CustomState], msg: LogMessage) {.gcsafe, noconv.} =
discard
proc stateWorker(source: ptr StatefulAppender) {.thread.} =
@@ -86,9 +89,9 @@ proc stateWorker(source: ptr StatefulAppender) {.thread.} =
var copied: StatefulAppender
withLock cloneLock:
copied = StatefulAppender(clone(source[]))
doAssert copied.state.value == 42
doAssert copied.state.snapshot().value == 42
proc makeFormatter(prefix: string): LogMessageFormatter =
proc makeFormatter(prefix: string): StatefulLogFormatterFunc =
result = proc(msg: LogMessage): string {.gcsafe.} = prefix & msg.msg
proc formatterWorker(source: ptr ConsoleLogAppender) {.thread.} =
@@ -100,7 +103,109 @@ proc formatterWorker(source: ptr ConsoleLogAppender) {.thread.} =
var copied: ConsoleLogAppender
withLock cloneLock:
copied = ConsoleLogAppender(clone(source[]))
doAssert copied.formatter(msg) == "prefix: message"
doAssert copied.formatter.format(msg) == "prefix: message"
type
SharedPayload = object
entries: seq[string]
destructions: ptr Atomic[int]
finalCount: ptr Atomic[int]
proc `=destroy`(value: SharedPayload) =
if value.destructions != nil:
value.finalCount[].store(value.entries.len)
value.destructions[].atomicInc()
`=destroy`(value.entries)
proc sharedStateWorker(source: ptr SharedLogState[SharedPayload]) {.thread.} =
let state = source[]
ready.atomicInc()
awaitStart()
for i in 0 ..< iterations:
var copied = state
let moved = move(copied)
moved.withState(proc(value: var SharedPayload) =
value.entries.add("entry")
doAssert value.entries[^1] == "entry")
type
FactoryState = ref object
count: int
self: FactoryState
output: SharedLogState[seq[int]]
proc makeState(output: SharedLogState[seq[int]]): FactoryState =
result = FactoryState(output: output)
result.self = result
proc logState(state: var FactoryState, msg: LogMessage) {.gcsafe, noconv.} =
inc state.count
doAssert state.self == state
let count = state.count
state.output.withState(proc(values: var seq[int]) = values.add(count))
proc factoryWorker(source: ptr LogService) {.thread.} =
block:
let local = source[].threadLocalRef()
ready.atomicInc()
awaitStart()
let logger = local.getLogger("worker")
let stamp = fromUnix(0).utc
for i in 0 ..< iterations:
logger.log(LogMessage(scope: "worker", level: lvlInfo, ts: stamp, msg: "message"))
GC_fullCollect()
proc timestampWorker() {.thread.} =
awaitStart()
for i in 0 ..< iterations:
let msg = initLogMessage("worker", lvlInfo, "message")
doAssert msg.msg == "message"
proc collectorWorker(collector: LoggedMessages) {.thread.} =
# Construct every managed field in this worker, including the timezone.
let stamp = fromUnix(0).utc
awaitStart()
for i in 0 ..< collectorIterations:
collector.add(LogMessage(scope: "worker", level: lvlInfo, ts: stamp,
msg: "message", err: some[ref Exception](newException(ValueError, "error")),
additionalData: %*{"number": i}))
var snapshot = collector.get()
doAssert snapshot.len > 0
doAssert snapshot[^1].err.get.msg == "error"
snapshot[0].msg = "private copy"
doAssert collector.get()[0].msg == "message"
type
FormatterSeed = object
prefix: string
destroyed: ptr Atomic[int]
FormatterProbeObj = object
count: int
destroyed: ptr Atomic[int]
FormatterProbe = ref FormatterProbeObj
proc `=destroy`(probe: FormatterProbeObj) =
if probe.destroyed != nil: probe.destroyed[].atomicInc()
proc makeCountedFormatter(seed: FormatterSeed): StatefulLogFormatterFunc =
let probe = FormatterProbe(destroyed: seed.destroyed)
result = proc(msg: LogMessage): string {.gcsafe.} =
inc probe.count
seed.prefix & $probe.count & msg.msg
proc formatterLifetimeWorker(source: ptr LogFormatter) {.thread.} =
block:
var formatter: LogFormatter
withLock cloneLock:
formatter = clone(source[])
ready.atomicInc()
awaitStart()
doAssert formatter.format(LogMessage(msg: "!")) == "count 1!"
for i in 0 ..< iterations:
let copied = clone(formatter)
doAssert copied.format(LogMessage(msg: "!")) == "count 1!"
doAssert copied.format(LogMessage(msg: "!")) == "count 2!"
GC_fullCollect()
proc main() =
doAssert paramCount() == 1
@@ -125,7 +230,7 @@ proc main() =
start.store(true)
joinThreads(workers)
of "custom-state":
var source = initCustomLogAppender(CustomState(value: 42), ignoreMessage)
var source = initCustomLogAppender(initSharedLogState(CustomState(value: 42)), ignoreMessage)
var workers: array[4, Thread[ptr StatefulAppender]]
for i in 0 ..< workers.len:
createThread(workers[i], stateWorker, addr source)
@@ -159,12 +264,71 @@ proc main() =
joinThreads(workers)
of "formatter":
var source = initConsoleLogAppender()
source.formatter = makeFormatter("prefix: ")
source.formatter = initLogFormatter("prefix: ", makeFormatter)
var workers: array[4, Thread[ptr ConsoleLogAppender]]
for i in 0 ..< workers.len:
createThread(workers[i], formatterWorker, addr source)
start.store(true)
joinThreads(workers)
of "shared-state-lifetime":
var destructions, finalCount: Atomic[int]
var state = initSharedLogState(SharedPayload(
destructions: addr destructions, finalCount: addr finalCount))
var workers: array[4, Thread[ptr SharedLogState[SharedPayload]]]
for i in 0 ..< workers.len:
createThread(workers[i], sharedStateWorker, addr state)
while ready.load() != workers.len: discard
state = default(typeof(state))
start.store(true)
joinThreads(workers)
doAssert destructions.load() == 1
doAssert finalCount.load() == workers.len * iterations
of "factory-state":
let output = initSharedLogState(newSeq[int]())
var service = initLogService()
service.addAppender(initFactoryCustomLogAppender(output, makeState, logState))
var workers: array[4, Thread[ptr LogService]]
for i in 0 ..< workers.len:
createThread(workers[i], factoryWorker, addr service)
while ready.load() != workers.len: discard
service = LogService()
start.store(true)
joinThreads(workers)
let values = output.snapshot()
doAssert values.len == workers.len * iterations
var counts: array[iterations + 1, int]
for value in values: inc counts[value]
for i in 1 .. iterations: doAssert counts[i] == workers.len
of "collector":
let collector = initLoggedMessages()
var workers: array[4, Thread[LoggedMessages]]
for i in 0 ..< workers.len:
createThread(workers[i], collectorWorker, collector)
start.store(true)
joinThreads(workers)
doAssert collector.get().len == workers.len * collectorIterations
of "formatter-lifetime":
var destroyed: Atomic[int]
var formatter = initLogFormatter(
FormatterSeed(prefix: "count ", destroyed: addr destroyed), makeCountedFormatter)
doAssert formatter.format(LogMessage(msg: "!")) == "count 1!"
var workers: array[4, Thread[ptr LogFormatter]]
for i in 0 ..< workers.len:
createThread(workers[i], formatterLifetimeWorker, addr formatter)
while ready.load() != workers.len: discard
formatter = nil
start.store(true)
joinThreads(workers)
GC_fullCollect()
doAssert destroyed.load() == 1 + workers.len * (iterations + 1)
of "timestamp":
var workers: array[4, Thread[void]]
for i in 0 ..< workers.len:
createThread(workers[i], timestampWorker)
start.store(true)
joinThreads(workers)
of "allocator":
runAllocatorRegression()
else:
raise newException(ValueError, "unknown thread safety scenario")