501 lines
19 KiB
Markdown
501 lines
19 KiB
Markdown
# Namespaced Logging for Nim
|
|
|
|
`namespaced_logging` is intended to be a high-performance, thread-safe logging
|
|
framework similar to [std/logging][std-logging] with support for
|
|
namespace-scoped logging similar to [log4j][] or [logback][] for Nim. It has
|
|
four main motivating features:
|
|
- Hierarchical, namespaced logging
|
|
- Safe and straightforward to use in multi-threaded applications.
|
|
- Native support for structured logging.
|
|
- Simple, autoconfigured usage pattern reminiscent of the
|
|
[std/logging][std-logging] interface (*not yet implemented*)
|
|
|
|
## Getting Started
|
|
|
|
Install the package via nimble:
|
|
|
|
```bash
|
|
# Not yet in official Nim packages. TODO once we've battle-tested it a little
|
|
nimble install https://github.com/jdbernard/nim-namespaced-logging
|
|
```
|
|
|
|
## Usage Patterns
|
|
|
|
### Manual Configuration
|
|
```nim
|
|
import namespaced_logging
|
|
|
|
# Manually creating a LogService. This is an independent logging root fully
|
|
# isolated from subsequent LogServices initialized with initLogService
|
|
var ls = initLogService()
|
|
|
|
# Configure logging
|
|
ls.addAppender(initConsoleLogAppender())
|
|
ls.addAppender(initFileLogAppender("app.log"))
|
|
ls.setThreshold("api", lvlWarn)
|
|
|
|
# Create loggers
|
|
let localLogSvc = threadLocalRef(ls)
|
|
let apiLogger = localLogSvc.getLogger("api")
|
|
let dbLogger = localLogSvc.getLogger("db")
|
|
```
|
|
|
|
### Manual Multithreaded Application
|
|
```nim
|
|
import namespaced_logging
|
|
|
|
# Main thread setup
|
|
var logService = initLogService()
|
|
logService.addAppender(initConsoleLogAppender())
|
|
|
|
var localLogSvc = threadLocalRef(logService) # for use on main thread
|
|
|
|
# Worker thread function
|
|
proc worker(ls: LogService) {.thread.} =
|
|
let localLogSvc = threadLocalRef(ls)
|
|
let logger = localLogSvc.getLogger("worker")
|
|
|
|
# Runtime configuration changes
|
|
localLogSvc.setThreshold("worker", lvlDebug)
|
|
logger.debug("Worker configured")
|
|
|
|
# Safe thread creation
|
|
createThread(workerThread, worker, logService)
|
|
```
|
|
|
|
### Dynamic Configuration
|
|
```nim
|
|
# Configuration can change at runtime
|
|
proc configureLogging(localLogSvc: ThreadLocalLogService, verbose: bool) =
|
|
if verbose:
|
|
localLogSvc.setRootThreshold(lvlDebug)
|
|
localLogSvc.addAppender(initFileLogAppender("debug.log"))
|
|
else:
|
|
localLogSvc.setRootThreshold(lvlInfo)
|
|
|
|
# Changes automatically propagate to all threads
|
|
```
|
|
|
|
## Loggers and Appenders
|
|
|
|
The logging system is composed of two main components: loggers and appenders.
|
|
Loggers are used to create log events, which are then passed to the appenders.
|
|
Appenders take log events and write them to some destination, such as the
|
|
console, a file, or a network socket. Appenders also have a logging level
|
|
threshold, which determines which log events are acted upon by the appender,
|
|
and, optionally, a namespace filter, which determines from which loggers the
|
|
appender accepts log events.
|
|
|
|
### Heirarchical Logging Namespaces
|
|
|
|
Loggers are organized hierarchically, with the hierarchy defined by the logger
|
|
scope. A logger with the scope `app/service/example` is conceptually a child of
|
|
the logger with the scope `app/service`. By default, appenders accept log
|
|
events from all loggers, but this can be restricted by setting a namespace
|
|
filter on the appender. An appender with a namespace set will accept log events
|
|
from all loggers with scopes that start with the namespace. For example, an
|
|
appender with the namespace `app` will accept log events from the loggers
|
|
`app`, `app/service`, and `app/service/example`, but not from `api/service`.
|
|
|
|
The other impact of the logger heirarchy is in the effective logging level of
|
|
the logger. An explicit logging level threshold can be set for any scope. Any
|
|
scope that does not have an explicit inherits its threshold from ancestor
|
|
loggers upwards in the scope naming heirarchy. This pattern is explained in
|
|
detail in the [logback documentation][effective logging level] and applies in
|
|
the same manner to loggers in this library.
|
|
|
|
### LogMessageFormater
|
|
|
|
Both the [ConsoleLogAppender](#ConsoleLogAppender) and
|
|
[FileLogAppender](#FileLogAppender) can be given a *LogMessageFormatter* to
|
|
determine how a log message is formatted before being written.
|
|
|
|
```nim
|
|
type LogMessageFormatter* = proc (msg: LogMessage): string {.gcsafe.}
|
|
```
|
|
|
|
## Available Appenders
|
|
|
|
### ConsoleLogAppender
|
|
|
|
Used for writing logs to stdout or stderr.
|
|
|
|
```nim
|
|
proc initConsoleLogAppender*(
|
|
formatter = formatSimpleTextLog,
|
|
## formatJsonStructuredLog is another useful formatter provided
|
|
## or you can write your own
|
|
useStderr = false, ## stdout is used by default
|
|
namespace = "", ## appender matches all scopes by default
|
|
threshold = lvlAll ## and accepts all message levels by default
|
|
): ConsoleLogAppender {.gcsafe.}
|
|
```
|
|
|
|
The first time a message is sent to any *ConsoleLogAppender*, we create a
|
|
writer thread which writes messages to the specified output in the order they
|
|
are received, flushing the file handle after each write to enforce an ordering.
|
|
The ConsoleLogAppender implementation uses a channel to send messages to the
|
|
writer thread.
|
|
|
|
### FileLogAppender
|
|
|
|
Used for writing logs to files.
|
|
|
|
```nim
|
|
proc initFileLogAppender*(
|
|
filePath: string,
|
|
formatter = formatSimpleTextLog,
|
|
## formatJsonStructuredLog is another useful formatter provided
|
|
## or you can write your own
|
|
namespace = "",
|
|
threshold = lvlAll
|
|
): FileLogAppender {.gcsafe.}
|
|
|
|
```
|
|
|
|
Similar to the *ConsoleLogAppender* implementation, the first time a message is
|
|
sent to any *FileLogAppender* we create a writer thread which writes messages
|
|
to files associated with the *FileLogAppender* configured for the current
|
|
*LogService*.
|
|
|
|
`namespaced_logging` does not currently have built-in logic for file
|
|
rotation, but it does play nice with external file rotation strategies. We do
|
|
not hold open file handles. The *FileLogAppender* attempts to batch messages
|
|
by destination file, opens the file with mode `fmAppend`, writes the current
|
|
batch of log messages, and then closes the file handle. Because of this, it has
|
|
no problem if another process moves or truncates any of the target log files.
|
|
|
|
### StdLoggingAppender
|
|
|
|
Provides a fallback to [std/logging][std-logging]-based logging. This is
|
|
primarily intended for use in libraries or other contexts where you want to
|
|
fall back to std/logging if the application is not using or hasn't configured
|
|
namespaced\_logging.
|
|
|
|
By default the *StdLoggingAppender* only logs when no namespaced\_logging
|
|
appenders are configured but it can also be configured to always forward log
|
|
messages regardless of whether namespaced\_logging has other appenders by
|
|
setting `fallbackOnly = false`.
|
|
|
|
```nim
|
|
func initStdLoggingAppender*(
|
|
fallbackOnly = true,
|
|
formatter = formatForwardedLog,
|
|
namespace = "",
|
|
threshold = lvlAll): StdLoggingAppender {.gcsafe.}
|
|
```
|
|
|
|
### CustomLogAppender
|
|
|
|
Provides an extension point for custom logging implementations.
|
|
|
|
```nim
|
|
func initCustomLogAppender*[T](
|
|
state: T, # arbitrary state needed for the appender
|
|
doLogMessage: CustomLogAppenderFunc[T],
|
|
# custom log appender implementation
|
|
namespace = "",
|
|
threshold = lvlAll): CustomLogAppender[T] {.gcsafe.} =
|
|
```
|
|
|
|
The `state` field allows you to explicitly pass in any data that is required
|
|
for the custom functionality.
|
|
|
|
> [!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 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
|
|
|
|
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 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.
|
|
|
|
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.
|
|
|
|
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.
|
|
|
|
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
|
|
|
|
### Overview
|
|
|
|
The namespaced logging library attempts to balance performance, safety, and
|
|
usability in multithreaded environments. The design centers on two key types:
|
|
*LogService* and *ThreadLocalLogService*.
|
|
|
|
#### LogService (Value Type)
|
|
```nim
|
|
type LogService* = object
|
|
shared: ptr SharedLogServiceState
|
|
```
|
|
|
|
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**: 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.
|
|
|
|
> [!TIP]
|
|
> The *LogService* object is the object that is intended to be shared across
|
|
> threads.
|
|
|
|
#### ThreadLocalLogService (Reference Type)
|
|
```nim
|
|
type ThreadLocalLogService* = ref object
|
|
serviceHandle: LogService
|
|
configVersion: int
|
|
appenders: seq[LogAppender]
|
|
thresholds: TableRef[string, Level]
|
|
```
|
|
|
|
*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.
|
|
|
|
> [!CAUTION]
|
|
> *ThreadLocalLogService* objects should **never** be shared outside the
|
|
> context of the thread in which they were initialized.
|
|
|
|
#### SharedLogServiceState (Internal)
|
|
|
|
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
|
|
- **Ownership**: Atomic retain/release and explicit destruction of configuration
|
|
- **Configuration versioning**: Atomic version numbers for efficient change
|
|
detection
|
|
|
|
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
|
|
var logService = initLogService()
|
|
logService.addAppender(initConsoleLogAppender())
|
|
|
|
# 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)
|
|
let logger = tlls.getLogger("worker")
|
|
logger.info("Worker thread started")
|
|
|
|
createThread(worker, workerThread, logService)
|
|
```
|
|
|
|
#### Unsafe Pattern (Avoided by Design)
|
|
```nim
|
|
# DON'T DO THIS - unsafe reference sharing
|
|
# ThreadLocalLogService should not be shared across threads
|
|
let tlls = threadLocalRef(initLogService())
|
|
createThread(worker, someProc, tlls) # ❌ Potential GC issues
|
|
```
|
|
|
|
### Configuration Synchronization
|
|
|
|
#### Atomic Version Checking
|
|
|
|
The library uses atomic version numbers to efficiently detect configuration
|
|
changes:
|
|
|
|
```nim
|
|
proc ensureFreshness*(ls: ThreadLocalLogService) =
|
|
# Cheap atomic check first
|
|
if ls.configVersion == ls.shared.configVersion.load():
|
|
return # No changes, return immediately
|
|
|
|
# Only acquire lock and copy if versions differ
|
|
withLock ls.shared.lock:
|
|
ls.configVersion = ls.shared.configVersion.load
|
|
# Sync state...
|
|
```
|
|
|
|
Goals/Motivation:
|
|
- Most logging operations skip expensive synchronization so the hot path is
|
|
fast.
|
|
- Propogate changes automatically so all threads see configuration updates.
|
|
- Minimize lock contention by only acquiring when configuration changes
|
|
|
|
#### Thread-Local Caching
|
|
|
|
Each thread maintains its own copy of the logging configuration in
|
|
*ThreadLocalLogService*:
|
|
|
|
- **Appenders**: Thread-local copies created via `clone()` method
|
|
- **Thresholds**: Complete copy of namespace-to-level mappings
|
|
- **Version tracking**: Local version number for change detection
|
|
|
|
This caching strategy provides:
|
|
- **High performance**: No locks needed for normal logging operations
|
|
- **Consistency**: All threads eventually see the same configuration
|
|
- **Isolation**: Thread-local state prevents cross-thread interference
|
|
|
|
## Error Handling
|
|
|
|
### Overview
|
|
|
|
For errors that occur during logging operations, there is a callback-based
|
|
error handling system designed to attempt to gracefully handle such failures.
|
|
Since logging is typically a non-critical operation we prioritize application
|
|
stability over guaranteed log delivery.
|
|
|
|
### Error Handler
|
|
|
|
The library uses a callback-based error handling pattern where applications can
|
|
register custom error handlers to be notified when logging operations fail. The
|
|
error handler receives:
|
|
- `error`: The exception that caused the failure
|
|
- `msg`: A descriptive message providing context about where the error occurred
|
|
|
|
```nim
|
|
type ErrorHandlerFunc* = proc(error: ref Exception, msg: string) {.gcsafe, nimcall.}
|
|
```
|
|
|
|
### Default Error Handler
|
|
|
|
namespaced\_logging uses the `defaultErrorHandlerFunc` if a custom error
|
|
handler has not been configured. The default handler:
|
|
|
|
1. Attempts to write to stderr, assuming it is likely to be available and monitored
|
|
2. Writes an error message and includes both the exception message and stack
|
|
trace (not available in release mode).
|
|
3. Fails silently if it is unable to write to to stderr.
|
|
|
|
### Configuration
|
|
|
|
#### Setting Custom Error Handlers
|
|
```nim
|
|
# During initialization
|
|
var logService = initLogService(errorHandler = myCustomErrorHandler)
|
|
|
|
# Or at runtime on either the LogService...
|
|
logService.setErrorHandler(myCustomErrorHandler)
|
|
|
|
# ... or on a ThreadLocalLogService
|
|
var localLogSvc = threadLocalRef(logService)
|
|
localLogSvc.setErrorHandler(myCustomErrorHandler)
|
|
```
|
|
|
|
#### Disabling Error Reporting
|
|
```nim
|
|
proc silentErrorHandler(err: ref Exception, msg: string) {.gcsafe, nimcall.} =
|
|
discard # Do nothing
|
|
|
|
logService.setErrorHandler(silentErrorHandler)
|
|
```
|
|
|
|
### Best Practices
|
|
|
|
#### Provide Fallbacks
|
|
|
|
```nim
|
|
proc robustErrorHandler(err: ref Exception, msg: string) {.gcsafe, nimcall.} =
|
|
# Primary: Send to monitoring system
|
|
if not sendToMonitoring(err, msg):
|
|
# Secondary: Write to dedicated error log
|
|
if not writeToErrorLog(err, msg):
|
|
# Tertiary: Use stderr as last resort
|
|
try:
|
|
stderr.writeLine("LOGGING ERROR [" & msg & "]: " & err.msg)
|
|
stderr.flushFile()
|
|
except: discard
|
|
```
|
|
|
|
#### Keep Error Handlers Simple
|
|
|
|
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
|
|
[atomic-load]: https://nim-lang.org/docs/atomics.html#load%2CAtomic%5BT%5D%2CMemoryOrder
|
|
[std-logging]: https://nim-lang.org/docs/logging.html
|
|
[testutil]: /blob/main/src/namespaced_logging/testutil.nim
|
|
[nsl-unit-tests]: https://github.com/jdbernard/nim-namespaced-logging/blob/main/src/namespaced_logging.nim#L904
|