refactor: Complete rewrite of logging system with thread-safe architecture

This commit represents a complete architectural overhaul of the namespaced
logging library, transitioning from a shared-memory approach to a robust
thread-safe design with proper synchronization primitives.

- **NEW**: internal `GlobalLogService` with atomic configuration versioning
- **NEW**: Thread-local configuration caching with freshness checking
- **NEW**: Separate `LogService` (copyable) and `ThreadLocalLogService` (ref)
- **REMOVED**: Manual thread state reloading in favor of automatic freshness

- All shared state protected by locks and atomics
- Configuration changes use atomic version numbers for efficient sync
- Proper cleanup with `=destroy` implementing graceful shutdown
- Thread-safe appender cloning via `clone()` method pattern

- **NEW**: Dedicated writer threads for console and file output
- **NEW**: Channel-based message passing to writer threads
- **NEW**: Batched file I/O with optimized write patterns
- **NEW**: Graceful thread shutdown on service destruction

- **NEW**: Configurable error handling with `ErrorHandlerFunc`
- **NEW**: `defaultErrorHandlerFunc` with stderr fallback
- **NEW**: Thread-safe error reporting with separate lock
- **NEW**: Robust error recovery in all I/O operations

- **NEW**: `autoconfigured` module for zero-config usage
- **NEW**: `formatSimpleTextLog` as default formatter
- **NEW**: Optional logger support for ergonomic usage
- **NEW**: Generic `CustomLogAppender[T]` with state parameter
- **NEW**: `FileLogAppender` with proper multithreaded file I/O
- **BREAKING**: Logger `name` field renamed to `scope`
- **BREAKING**: Configuration methods renamed (e.g., `setRootLevel` → `setRootThreshold`)

- **NEW**: Comprehensive test suite with 20+ test cases
- **NEW**: `testutil` module with thread-safe test infrastructure
- **NEW**: Cross-thread synchronization testing
- **NEW**: File I/O testing with temporary files
- **REMOVED**: Old test suite replaced with more comprehensive version

- Atomic version checking prevents unnecessary config copies
- Writer threads use efficient polling with 100ms idle sleep
- File writer batches messages and optimizes file operations
- Thread-local caching reduces lock contention

1. **API Changes**:
   - `LogService` returned by `iniLogService` is fundamentally different
   - `threadLocalRef()` required for thread-local operations
   - `reloadThreadState()` removed (automatic freshness)
   - Logger field `name` → `scope`

2. **Configuration**:
   - `setRootLevel()` → `setRootThreshold()`
   - `setThreshold()` API simplified
   - `clearAppenders()` removed

3. **Appenders**:
   - `initThreadCopy()` → `clone()`
   - `appendLogMessage()` signature changed
   - Custom appenders now generic with state parameter

```nim
let ls = initLogService()
ls.addAppender(initConsoleLogAppender())
reloadThreadState(ls)
let logger = ls.getLogger("app")
logger.info("Hello world")
```

```nim
let ls = initLogService()
let tlls = threadLocalRef(ls)
tlls.addAppender(initConsoleLogAppender())
let logger = tlls.getLogger("app")
logger.info("Hello world")
```
```nim
import namespaced_logging/autoconfigured
addLogAppender(initConsoleLogAppender())
info("Hello world")
```
This commit is contained in:
2025-07-05 11:16:47 -05:00
parent e0dba8125c
commit f80e5807db
6 changed files with 1100 additions and 502 deletions

2
.gitignore vendored
View File

@ -1,3 +1,5 @@
.*.sw?
nimcache/
tests/tests
src/namespaced_logging.out
src/namespaced_logging/autoconfigured

File diff suppressed because it is too large Load Diff

View File

@ -0,0 +1,98 @@
import std/[json, options]
from logging import Level
import ../namespaced_logging
export
# Types
Level,
Logger,
LogAppender,
LogMessage,
ConsoleLogAppender,
CustomLogAppender,
CustomLogAppenderFunction,
FileLogAppender,
# Procs/Funcs
`%`,
initConsoleLogAppender,
initCustomLogAppender,
initFileLogAppender,
formatJsonStructuredLog
var globalLogServiceRef: ThreadLocalLogService = new(LogService)
globalLogServiceRef[] = initLogService()
var threadLocalLogServiceRef {.threadvar.}: ThreadLocalLogService
var defaultLogger {.threadvar.}: Option[Logger]
proc getThreadLocalLogServiceRef(): ThreadLocalLogService {.inline.} =
if threadLocalLogServiceRef.isNil:
threadLocalLogServiceRef = new(LogService)
threadLocalLogServiceRef[] = globalLogServiceRef[]
return threadLocalLogServiceRef
proc getDefaultLogger(): Logger {.inline.} =
if defaultLogger.isNone:
defaultLogger = some(getThreadLocalLogServiceRef().getLogger(""))
return defaultLogger.get
proc useForAutoconfiguredLogging*(ls: LogService) =
globalLogServiceRef[] = ls
proc setRootLoggingThreshold*(lvl: Level) =
setRootThreshold(getThreadLocalLogServiceRef(), lvl)
proc setLoggingThreshold*(scope: string, lvl: Level) =
setThreshold(getThreadLocalLogServiceRef(), scope, lvl)
proc addLogAppender*(appender: LogAppender) =
addAppender(getThreadLocalLogServiceRef(), appender)
proc getLogger*(scope: string, lvl: Option[Level] = none[Level]()): Logger =
getLogger(getThreadLocalLogServiceRef(), scope, lvl)
proc log*(lvl: Level, msg: string) = getDefaultLogger().log(lvl, msg)
proc log*(lvl: Level, msg: JsonNode) = getDefaultLogger().log(lvl, msg)
proc log*(lvl: Level, error: ref Exception, msg: string) =
getDefaultLogger().log(lvl, error, msg)
template debug*[T](msg: T) = log(lvlDebug, msg)
template info*[T](msg: T) = log(lvlInfo, msg)
template notice*[T](msg: T) = log(lvlNotice, msg)
template warn*[T](msg: T) = log(lvlWarn, msg)
template error*[T](msg: T) = log(lvlError, msg)
template error*(error: ref Exception, msg: string) = log(lvlError, error, msg)
template fatal*[T](msg: T) = log(lvlFatal, msg)
template fatal*(error: ref Exception, msg: string) = log(lvlFatal, error, msg)
when isMainModule:
import std/unittest
import ./testutil
suite "Autoconfigured Logging":
setup:
globalLogServiceRef[] = initLogService()
let loggedMessages = initLoggedMessages()
let testAppender = initTestLogAppender(loggedMessages)
test "simple no-config logging":
addLogAppender(testAppender)
info("test message")
let lm = loggedMessages.get()
check:
lm.len == 1
lm[0].level == lvlInfo
lm[0].message == "test message"

View File

@ -0,0 +1,51 @@
import std/[locks, sequtils, syncio, os, times]
from logging import Level
from ../namespaced_logging import CustomLogAppender, initCustomLogAppender, LogMessage
type
LoggedMessages* = ref object
messages*: seq[LogMessage]
lock: Lock
proc initLoggedMessages*(): LoggedMessages =
result = LoggedMessages(messages: @[])
initLock(result.lock)
proc add*(lm: LoggedMessages, msg: LogMessage) =
withLock lm.lock: lm.messages.add(msg)
proc clear*(lm: LoggedMessages) =
withLock lm.lock: lm.messages = @[]
proc get*(lm: LoggedMessages): seq[LogMessage] =
withLock lm.lock: return lm.messages.mapIt(it)
proc testLogAppenderProc(state: LoggedMessages, msg: LogMessage) {.gcsafe, noconv.} =
state.add(msg)
proc initTestLogAppender*(
lm: LoggedMessages,
namespace = "",
threshold = lvlAll): CustomLogAppender[LoggedMessages] =
initCustomLogAppender(
state = lm,
doLogMessage = testLogAppenderProc,
namespace = namespace,
threshold = threshold)
proc waitForFileContent*(
path: string,
expectedLines: int,
timeoutMs: int = 1000): seq[string] =
let startTime = getTime()
while (getTime() - startTime).inMilliseconds < timeoutMs:
if fileExists(path):
result = readLines(path)
if result.len >= expectedLines: break
sleep(10)

View File

@ -1 +0,0 @@
--path:"../src"

View File

@ -1,303 +0,0 @@
import std/[json, locks, options, strutils, unittest]
import namespaced_logging, zero_functional
type
TestLogAppender = ref object of LogAppender
statePtr: ptr TestLogState
TestLogState = object
logs: seq[(string, LogMessage)]
lock: Lock
var sharedTestLogState: ptr TestLogState
proc initSharedTestLogState() =
sharedTestLogState = cast[ptr TestLogState](allocShared0(sizeof(TestLogState)))
sharedTestLogState.logs = @[]
method appendLogMessage*(tla: TestLogAppender, msg: LogMessage): void {.gcsafe.} =
if msg.level < tla.threshold: return
acquire(sharedTestLogState.lock)
sharedTestLogState.logs.add((tla.namespace, msg))
release(sharedTestLogState.lock)
method initThreadCopy*(tla: TestLogAppender): LogAppender {.gcsafe.} =
TestLogAppender(
namespace: tla.namespace,
threshold: tla.threshold,
statePtr: tla.statePtr)
proc initTestLogAppender(namespace = "", threshold = lvlAll): TestLogAppender =
TestLogAppender(
namespace: namespace,
threshold: threshold,
statePtr: sharedTestLogState)
initSharedTestLogState()
suite "initialization":
test "can create LogService":
let logSvc = initLogService()
check:
not logSvc.isNil
test "reloadThreadState":
let logSvc = initLogService()
reloadThreadState(logSvc)
test "create Logger":
let logSvc = initLogService()
let logger = logSvc.getLogger("test")
check:
logger.threshold.isNone
logger.name == "test"
test "create Logger with threshold":
let logSvc = initLogService()
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test", some(lvlDebug))
check:
logger.threshold.isSome
logger.threshold.get == lvlDebug
logger.name == "test"
test "initConsoleLogAppender":
let cla = initConsoleLogAppender()
suite "log methods":
test "log with ConsoleLogAppender":
let logSvc = initLogService()
let cla = initConsoleLogAppender(threshold = lvlDebug)
let tla = initTestLogAppender()
logSvc.addAppender(cla)
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test")
logger.info("Test log message.")
acquire(sharedTestLogState.lock)
check sharedTestLogState.logs.len == 1
let log = sharedTestLogState.logs[0][1]
check:
log.message == "Test log message."
log.level == lvlInfo
log.scope == "test"
log.error.isNone
log.additionalData.kind == JNull
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "log with error":
let logSvc = initLogService()
let tla = initTestLogAppender()
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test")
logger.error(newException(Exception, "Test error message."), "exception occurred")
acquire(sharedTestLogState.lock)
check sharedTestLogState.logs.len == 1
let log = sharedTestLogState.logs[0][1]
check:
log.message == "exception occurred"
log.level == lvlError
log.scope == "test"
log.error.isSome
log.error.get.name == "Exception"
log.error.get.msg == "Test error message."
log.additionalData.kind == JNull
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
suite "namespaces":
test "appenders at the root level accept all messages":
let logSvc = initLogService()
let tla = initTestLogAppender()
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let l1 = logSvc.getLogger("")
let l2 = logSvc.getLogger("test")
let l3 = logSvc.getLogger("test/sub")
l1.info("message from root")
l2.info("message from test")
l3.info("message from test/sub")
acquire(sharedTestLogState.lock)
let logs = sharedTestLogState.logs
check:
logs.len == 3
logs[0][1].message == "message from root"
logs[1][1].message == "message from test"
logs[2][1].message == "message from test/sub"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "appenders accept messages at their namespace":
let logSvc = initLogService()
let tla = initTestLogAppender(namespace = "test")
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test")
logger.info("message from test")
acquire(sharedTestLogState.lock)
check:
sharedTestLogState.logs.len == 1
sharedTestLogState.logs[0][0] == "test"
sharedTestLogState.logs[0][1].message == "message from test"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "appenders accept messages from scopes within their namespace":
let logSvc = initLogService()
let tlaRoot = initTestLogAppender(namespace = "")
let tlaTest = initTestLogAppender(namespace = "test")
logSvc.addAppender(tlaRoot)
logSvc.addAppender(tlaTest)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test/sub")
logger.info("message from test/sub")
acquire(sharedTestLogState.lock)
let logs = sharedTestLogState.logs
check:
logs.len == 2
logs[0][0] == ""
logs[0][1].message == "message from test/sub"
logs[1][0] == "test"
logs[1][1].message == "message from test/sub"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "appenders do not accept messages outside their namespace":
let logSvc = initLogService()
let tlaRoot = initTestLogAppender(namespace = "")
let tlaTest = initTestLogAppender(namespace = "test")
logSvc.addAppender(tlaRoot)
logSvc.addAppender(tlaTest)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("other")
logger.info("message from other")
acquire(sharedTestLogState.lock)
let logs = sharedTestLogState.logs
check:
logs.len == 1
logs[0][0] == ""
logs[0][1].message == "message from other"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
suite "thresholds":
test "logger gates messages by level":
let logSvc = initLogService()
let tla = initTestLogAppender()
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test", some(lvlInfo))
logger.debug("message at debug level")
logger.info("message at info level")
logger.warn("message at warn level")
acquire(sharedTestLogState.lock)
let logs = sharedTestLogState.logs
check:
logs.len == 2
logs[0][1].message == "message at info level"
logs[1][1].message == "message at warn level"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "root threshold applies when logger has none":
let logSvc = initLogService(lvlWarn)
let tla = initTestLogAppender()
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("test")
logger.debug("message at debug level")
logger.info("message at info level")
logger.warn("message at warn level")
acquire(sharedTestLogState.lock)
let logs = sharedTestLogState.logs
check:
logs.len == 1
logs[0][1].message == "message at warn level"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "logger inherits effective threshold from ancestors":
let logSvc = initLogService()
let tla = initTestLogAppender()
logSvc.addAppender(tla)
reloadThreadState(logSvc)
let l1 = logSvc.getLogger("test", some(lvlInfo))
let l2 = logSvc.getLogger("test/sub")
let l3 = logSvc.getLogger("test/sub/subsub")
let l4 = logSvc.getLogger("other")
l3.debug("message at debug level")
l3.info("message at info level")
l3.warn("message at warn level")
l4.debug("message at debug level")
acquire(sharedTestLogState.lock)
let l3Logs = sharedTestLogState.logs --> filter(it[1].scope == "test/sub/subsub")
let l4Logs = sharedTestLogState.logs --> filter(it[1].scope == "other")
check:
l3Logs.len == 2
l3Logs[0][1].message == "message at info level"
l3Logs[1][1].message == "message at warn level"
l4Logs.len == 1
l4Logs[0][1].message == "message at debug level"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)
test "appender gates messages by level":
let logSvc = initLogService()
let tlaInfo = initTestLogAppender(namespace="a", threshold = lvlInfo)
let tlaDebug = initTestLogAppender(namespace="a/b", threshold = lvlDebug)
logSvc.addAppender(tlaInfo)
logSvc.addAppender(tlaDebug)
reloadThreadState(logSvc)
let logger = logSvc.getLogger("a/b")
logger.debug("message at debug level")
logger.info("message at info level")
logger.warn("message at warn level")
acquire(sharedTestLogState.lock)
let aLogs = sharedTestLogState.logs --> filter(it[0] == "a")
let bLogs = sharedTestLogState.logs --> filter(it[0] == "a/b")
check:
aLogs.len == 2
aLogs[0][1].message == "message at info level"
aLogs[1][1].message == "message at warn level"
bLogs.len == 3
bLogs[0][1].message == "message at debug level"
bLogs[1][1].message == "message at info level"
bLogs[2][1].message == "message at warn level"
sharedTestLogState.logs.setLen(0)
release(sharedTestLogState.lock)