Compare commits
1
Commits
9fa158f68d
..
2.0.0
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
3e7f3d4c1e |
No files matched your search
@@ -1,10 +1,5 @@
|
|||||||
.*.sw?
|
.*.sw?
|
||||||
nimcache/
|
nimcache/
|
||||||
tests/tests
|
tests/tests
|
||||||
tests/bin/
|
|
||||||
src/namespaced_logging.out
|
src/namespaced_logging.out
|
||||||
src/namespaced_logging/autoconfigured
|
src/namespaced_logging/autoconfigured
|
||||||
.worktrees
|
|
||||||
nimble.develop
|
|
||||||
nimble.paths
|
|
||||||
nimbledeps
|
|
||||||
@@ -1,89 +0,0 @@
|
|||||||
# Changelog
|
|
||||||
|
|
||||||
## 3.0.0
|
|
||||||
|
|
||||||
This release reworks logging ownership for Nim's ORC memory manager, fixes
|
|
||||||
background writer shutdown, and switches generated timestamps to UTC. It
|
|
||||||
introduces breaking API changes from 2.1.2. Nim 2.2.0 or later remains required.
|
|
||||||
|
|
||||||
### Breaking changes and migration
|
|
||||||
|
|
||||||
- **Service handles and local caches are separate types.** `LogService` is now
|
|
||||||
a copyable handle that keeps shared configuration alive. Pass a copy to each
|
|
||||||
worker, then call `threadLocalRef()` inside that worker. Keep
|
|
||||||
`ThreadLocalLogService` and its loggers in the thread that creates them. Use
|
|
||||||
`local.service` instead of `local[]` to obtain a shared handle.
|
|
||||||
- **`ensureFreshness(LogService)` has been removed.** Refresh the relevant
|
|
||||||
`ThreadLocalLogService` instead. Configuration methods remain available on
|
|
||||||
both types; `LogService.appenders()` returns clones of the current shared
|
|
||||||
configuration.
|
|
||||||
- **Custom appender callbacks now receive `state: var T`.**
|
|
||||||
`initCustomLogAppender` copies supported value state into each clone and
|
|
||||||
rejects ordinary references, closures, and embedded synchronization
|
|
||||||
primitives, including nested ones. Use `SharedLogState[T]` for shared mutable
|
|
||||||
value data, or `initFactoryCustomLogAppender` for independently created state
|
|
||||||
containing references or closures.
|
|
||||||
- **Appenders now accept `LogFormatter` objects.** The former
|
|
||||||
`LogMessageFormatter` callback type is replaced by `StatefulLogFormatterFunc`
|
|
||||||
and `StatelessLogFormatterFunc`. Noncapturing formatter functions still
|
|
||||||
convert automatically. Replace directly supplied captured closures with
|
|
||||||
`initLogFormatter(seed, factory)`, and use `formatter.format(message)` to
|
|
||||||
invoke a formatter directly. Custom appender and formatter clones must own
|
|
||||||
independent state or use explicit shared-state handles.
|
|
||||||
- **Generated timestamps now use UTC.** `LogMessage.ts` remains a `DateTime`;
|
|
||||||
structured JSON output uses a `Z` suffix. Explicit timestamps supplied in
|
|
||||||
caller-constructed messages are preserved.
|
|
||||||
- **The test collector returns value snapshots.** `LoggedMessages.get()` now
|
|
||||||
returns `seq[RecordedLogMessage]` instead of `seq[LogMessage]`. Timestamps are
|
|
||||||
`Time` values, additional JSON data is serialized text, and exceptions retain
|
|
||||||
their name, message, and stacktrace as text. Use the collector's methods
|
|
||||||
instead of accessing its former `messages` field.
|
|
||||||
|
|
||||||
### Added
|
|
||||||
|
|
||||||
- `SharedLogState[T]` and `initSharedLogState` provide copyable ownership of
|
|
||||||
shared value data. Use `withState` for synchronized updates and `snapshot`
|
|
||||||
for independent copies. Raw pointers and custom copy/destruction hooks
|
|
||||||
remain the caller's responsibility.
|
|
||||||
- `FactoryCustomLogAppender` and `initFactoryCustomLogAppender` create custom
|
|
||||||
state lazily within the thread using each clone. Formatter factories provide
|
|
||||||
the same ownership pattern for captured formatter state. Configuration
|
|
||||||
refresh can replace clones and reset their local state; use shared-state
|
|
||||||
handles for data that must persist across refreshes.
|
|
||||||
|
|
||||||
### Fixed and clarified
|
|
||||||
|
|
||||||
- Service copies retain shared configuration without sharing ordinary ORC
|
|
||||||
reference ownership between threads. Workers can outlive the original
|
|
||||||
handle and the thread that created it.
|
|
||||||
- Local caches are built independently. Failed configuration refreshes preserve
|
|
||||||
the previous cache and retry on a later refresh without requiring another
|
|
||||||
configuration change.
|
|
||||||
- Background console and file writers drain queued records at normal process
|
|
||||||
exit, including empty messages and the final file batch. Shutdown excludes
|
|
||||||
further submissions and waits for writers to finish. Applications must join
|
|
||||||
their logging workers before exiting.
|
|
||||||
- Both message constructors avoid local-time conversion races by creating UTC
|
|
||||||
timestamps directly.
|
|
||||||
- `isEnabled` intentionally checks cached namespace thresholds without
|
|
||||||
refreshing configuration. Logging calls, `getLogger`, or an explicit local
|
|
||||||
refresh pick up changes. Applications that guard all logging should refresh
|
|
||||||
at suitable boundaries, such as the start of a request. The shared root
|
|
||||||
threshold is read only when no cached namespace threshold applies.
|
|
||||||
|
|
||||||
### Tests and known limitations
|
|
||||||
|
|
||||||
- `nimble test` runs all enabled unit, regression, and ThreadSanitizer suites
|
|
||||||
under ORC with threads enabled. Individual suites remain available through
|
|
||||||
`testUnit`, `testRegression`, and `testThreadSafety`.
|
|
||||||
- Validation passes 32 unit tests, 29 regression tests, and 11 sanitizer
|
|
||||||
scenarios. Two scenarios, `factory-state` and `allocator`, are temporarily
|
|
||||||
skipped because they expose a known race in Nim 2.2.10's default allocator.
|
|
||||||
Their code and assertions remain available; enable them with
|
|
||||||
`NSL_TEST_RUNTIME_ALLOCATOR=1 nimble testThreadSafety`.
|
|
||||||
- The allocator limitation remains unresolved and also reproduces without
|
|
||||||
importing this library. Passing the enabled tests does not establish full
|
|
||||||
validation of factory state under the default allocator. See
|
|
||||||
[the test documentation](tests/README.md) for details and diagnostic results.
|
|
||||||
|
|
||||||
See the [README](README.md) for usage and migration examples.
|
|
||||||
@@ -1,110 +1,38 @@
|
|||||||
# Namespaced Logging for Nim
|
# Namespaced Logging for Nim
|
||||||
|
|
||||||
`namespaced_logging` is intended to be a high-performance, thread-safe logging
|
`namespaced_logging` provides a logging framework similar to [log4j][] or
|
||||||
framework similar to [std/logging][std-logging] with support for
|
[logback][] for Nim. It has three main motivating features:
|
||||||
namespace-scoped logging similar to [log4j][] or [logback][] for Nim. It has
|
|
||||||
four main motivating features:
|
|
||||||
- Hierarchical, namespaced logging
|
- Hierarchical, namespaced logging
|
||||||
- Safe and straightforward to use in multi-threaded applications.
|
- Safe and straightforward to use in multi-threaded applications.
|
||||||
- Native support for structured logging.
|
- Native support for structured logging (old-style string logging is also
|
||||||
- Simple, autoconfigured usage pattern reminiscent of the
|
supported).
|
||||||
[std/logging][std-logging] interface (*not yet implemented*)
|
|
||||||
|
|
||||||
## Getting Started
|
## Getting Started
|
||||||
|
|
||||||
See the [changelog](CHANGELOG.md) for version 3.0.0 changes and migration notes.
|
Install the package from nimble:
|
||||||
|
|
||||||
Install the package via nimble:
|
|
||||||
|
|
||||||
```bash
|
```bash
|
||||||
# Not yet in official Nim packages. TODO once we've battle-tested it a little
|
nimble install namespaced_logging
|
||||||
nimble install https://github.com/jdbernard/nim-namespaced-logging
|
|
||||||
```
|
```
|
||||||
|
|
||||||
## Usage Patterns
|
Then, in your application, you can use the logging system like so:
|
||||||
|
|
||||||
### Manual Configuration
|
|
||||||
```nim
|
```nim
|
||||||
import namespaced_logging
|
import namespaced_logging
|
||||||
|
|
||||||
# Manually creating a LogService. This is an independent logging root fully
|
# On the main thread
|
||||||
# isolated from subsequent LogServices initialized with initLogService
|
let logService = initLogService()
|
||||||
var ls = initLogService()
|
logService.addAppender(initConsoleAppender(LogLevel.INFO))
|
||||||
|
|
||||||
# Configure logging
|
# On any thread, including the main thread
|
||||||
ls.addAppender(initConsoleLogAppender())
|
let logger = logService.getLogger("app/service/example")
|
||||||
ls.addAppender(initFileLogAppender("app.log"))
|
logger.info("Log from the example service")
|
||||||
ls.setThreshold("api", lvlWarn)
|
|
||||||
|
|
||||||
# Create loggers
|
# Only get logs at the WARN or higher level from the database module
|
||||||
let localLogSvc = threadLocalRef(ls)
|
let logger = logService.getLogger("app/database", threshold = some(Level.lvlWarn))
|
||||||
let apiLogger = localLogSvc.getLogger("api")
|
logger.error("Database connection failed")
|
||||||
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
|
|
||||||
```
|
|
||||||
|
|
||||||
### Avoiding Expensive Log Preparation
|
|
||||||
|
|
||||||
Use `isEnabled` to guard expensive work performed before a logging call:
|
|
||||||
|
|
||||||
```nim
|
|
||||||
if logger.isEnabled(lvlDebug):
|
|
||||||
let details = buildExpensiveDetails()
|
|
||||||
logger.debug(details)
|
|
||||||
```
|
|
||||||
|
|
||||||
`isEnabled` checks the logger's effective threshold without refreshing its
|
|
||||||
configuration. It uses cached namespace thresholds and the shared root fallback
|
|
||||||
level. Namespace changes can remain unseen until the local service refreshes.
|
|
||||||
Normal logging calls and `getLogger` refresh the cache; callers can also use
|
|
||||||
`ensureFreshness(localLogSvc)` explicitly.
|
|
||||||
|
|
||||||
If all logging is guarded by `isEnabled`, a cached disabled level can keep
|
|
||||||
skipping those logging calls indefinitely. To pick up runtime namespace changes
|
|
||||||
in that situation, refresh the local service at suitable application boundaries,
|
|
||||||
such as the start of a request or work batch.
|
|
||||||
|
|
||||||
A true result does not guarantee delivery: the logging call refreshes
|
|
||||||
configuration and appenders apply their own filters. For a single expression,
|
|
||||||
`logger.debug(buildExpensiveDetails())` already delays evaluation until the
|
|
||||||
logger's threshold permits the message. A separate guard is useful when
|
|
||||||
preparation requires multiple statements.
|
|
||||||
|
|
||||||
## Loggers and Appenders
|
## Loggers and Appenders
|
||||||
|
|
||||||
The logging system is composed of two main components: loggers and appenders.
|
The logging system is composed of two main components: loggers and appenders.
|
||||||
@@ -115,493 +43,140 @@ threshold, which determines which log events are acted upon by the appender,
|
|||||||
and, optionally, a namespace filter, which determines from which loggers the
|
and, optionally, a namespace filter, which determines from which loggers the
|
||||||
appender accepts log events.
|
appender accepts log events.
|
||||||
|
|
||||||
### Heirarchical Logging Namespaces
|
### Heirarchical Logging and Namespaces
|
||||||
|
|
||||||
Loggers are organized hierarchically, with the hierarchy defined by the logger
|
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
|
name. A logger with the name `app/service/example` is a child of the logger
|
||||||
the logger with the scope `app/service`. By default, appenders accept log
|
with the name `app/service`. By default, appenders accept log events from all
|
||||||
events from all loggers, but this can be restricted by setting a namespace
|
loggers, but this can be restricted by setting a namespace filter on the
|
||||||
filter on the appender. An appender with a namespace set will accept log events
|
appender. An appender with a namespace set will accept log events from all
|
||||||
from all loggers with scopes that start with the namespace. For example, an
|
loggers with names that start with the namespace. For example, an appender with
|
||||||
appender with the namespace `app` will accept log events from the loggers
|
the namespace `app` will accept log events from the loggers `app`,
|
||||||
`app`, `app/service`, and `app/service/example`, but not from `api/service`.
|
`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 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
|
the logger. Any logger can have an explicit logging level set, but if it does
|
||||||
scope that does not have an explicit inherits its threshold from ancestor
|
not, the effective logging level is inherited from ancestor loggers upwards in
|
||||||
loggers upwards in the scope naming heirarchy. This pattern is explained in
|
the logger heirarchy. This pattern is explained in detail in the [logback
|
||||||
detail in the [logback documentation][effective logging level] and applies in
|
documentation][effective logging level] and applies in the same manner to
|
||||||
the same manner to loggers in this library.
|
loggers in this library.
|
||||||
|
|
||||||
### LogFormatter
|
|
||||||
|
|
||||||
Messages created by the library carry UTC timestamps in `LogMessage.ts`, which
|
|
||||||
remains a `DateTime`. This changes the previous local-time behavior. Structured
|
|
||||||
JSON output represents these timestamps with a `Z` suffix. Explicit timestamps
|
|
||||||
in caller-constructed `LogMessage` values are preserved.
|
|
||||||
|
|
||||||
Console, file, and std/logging appenders accept a *LogFormatter*. Noncapturing
|
|
||||||
functions such as *formatSimpleTextLog* and *formatJsonStructuredLog* are
|
|
||||||
converted automatically:
|
|
||||||
|
|
||||||
```nim
|
|
||||||
let appender = initConsoleLogAppender(formatter = formatJsonStructuredLog)
|
|
||||||
```
|
|
||||||
|
|
||||||
For a formatter that captures state, pass value configuration and a
|
|
||||||
noncapturing factory to *initLogFormatter*. The factory creates a separate
|
|
||||||
closure in each thread on first use:
|
|
||||||
|
|
||||||
```nim
|
|
||||||
proc makeFormatter(prefix: string): StatefulLogFormatterFunc =
|
|
||||||
var count = 0
|
|
||||||
result = proc(msg: LogMessage): string {.gcsafe.} =
|
|
||||||
inc count
|
|
||||||
prefix & $count & ": " & msg.msg
|
|
||||||
|
|
||||||
let appender = initConsoleLogAppender(
|
|
||||||
formatter = initLogFormatter("request ", makeFormatter))
|
|
||||||
```
|
|
||||||
|
|
||||||
The factory's input must contain value data, such as strings, sequences of
|
|
||||||
values, or *SharedLogState* handles. Ordinary `ref` values and closures are
|
|
||||||
rejected, including when nested inside other types. The returned closure may
|
|
||||||
capture independently created references and mutable state belonging to its
|
|
||||||
thread. It must not return a closure shared with another thread.
|
|
||||||
|
|
||||||
Each appender clone starts fresh formatter state; configuration refresh can
|
|
||||||
reate new clones. For counters or other data that must persist across
|
|
||||||
refreshes or be shared between threads, pass a *SharedLogState* handle as
|
|
||||||
factory input. To invoke a formatter directly, use
|
|
||||||
`formatter.format(message)`.
|
|
||||||
|
|
||||||
|
|
||||||
## Available Appenders
|
|
||||||
|
|
||||||
### ConsoleLogAppender
|
|
||||||
|
|
||||||
Used for writing logs to stdout or stderr.
|
|
||||||
|
|
||||||
```nim
|
|
||||||
proc initConsoleLogAppender*(
|
|
||||||
formatter: LogFormatter = nil, # defaults to 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: LogFormatter = nil, # defaults to 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
|
|
||||||
proc initStdLoggingAppender*(
|
|
||||||
fallbackOnly = true,
|
|
||||||
formatter: LogFormatter = nil, # defaults to formatForwardedLog
|
|
||||||
namespace = "",
|
|
||||||
threshold = lvlAll): StdLoggingAppender {.gcsafe.}
|
|
||||||
```
|
|
||||||
|
|
||||||
### CustomLogAppender
|
|
||||||
|
|
||||||
Provides an extension point for custom logging implementation.
|
|
||||||
|
|
||||||
Use *initCustomLogAppender* for state that can be copied by value. Its callback
|
|
||||||
receives `state: var T` and a *LogMessage*. Each clone owns a separate state
|
|
||||||
value. Ordinary `ref` values, closures, and embedded locks or atomics are
|
|
||||||
rejected, including inside containers and objects.
|
|
||||||
|
|
||||||
For mutable state shared by all workers, put value data in a *SharedLogState*:
|
|
||||||
|
|
||||||
```nim
|
|
||||||
let count = initSharedLogState(0)
|
|
||||||
|
|
||||||
proc countMessage(state: var SharedLogState[int], msg: LogMessage) {.gcsafe, noconv.} =
|
|
||||||
state.withState(proc(value: var int) = inc value)
|
|
||||||
|
|
||||||
var service = initLogService()
|
|
||||||
service.addAppender(initCustomLogAppender(count, countMessage))
|
|
||||||
# Pass service copies to workers as described below.
|
|
||||||
# count.snapshot() reads the current count safely.
|
|
||||||
```
|
|
||||||
|
|
||||||
Copies of the handle share the same data and keep it alive. *withState* runs
|
|
||||||
its callback synchronously with exclusive access; *snapshot* returns a value
|
|
||||||
copy made under the same lock. Neither operation allows unsynchronized access
|
|
||||||
to the stored payload. Do not retain a pointer to the callback's argument or
|
|
||||||
call back into the same handle from inside *withState*, since its lock is not
|
|
||||||
recursive.
|
|
||||||
|
|
||||||
The payload must contain value data without ordinary references, closures, or
|
|
||||||
embedded synchronization primitives. Strings and sequences of supported values
|
|
||||||
are accepted. Raw pointers and types with custom copy/destruction hooks remain
|
|
||||||
an explicit caller responsibility: their lifetime and synchronization must be
|
|
||||||
safe across threads. *SharedLogState* does not make a raw pointer's target
|
|
||||||
safe.
|
|
||||||
|
|
||||||
The [testutil][] collector demonstrates shared state using value snapshots.
|
|
||||||
*LoggedMessages.get()* returns `seq[RecordedLogMessage]`: timestamps are
|
|
||||||
*Time* values, additional JSON data is serialized text, and exceptions retain
|
|
||||||
name, message, and stacktrace text. Returned snapshots can be inspected and
|
|
||||||
modified independently without sharing the original message's references.
|
|
||||||
|
|
||||||
### FactoryCustomLogAppender
|
|
||||||
|
|
||||||
Provides an extension point for custom logging with state created separately
|
|
||||||
in each logging thread. Use this when state needs ordinary references or
|
|
||||||
closures owned by that thread.
|
|
||||||
|
|
||||||
Call *initFactoryCustomLogAppender(seed, factory, doLogMessage)* during logging
|
|
||||||
setup. The noncapturing factory receives a copyable value seed and creates
|
|
||||||
independently owned state on the first message handled by each clone, in the
|
|
||||||
thread doing the logging. The logging callback receives `state: var T` and a
|
|
||||||
*LogMessage*.
|
|
||||||
|
|
||||||
The seed follows the same ownership restrictions as *CustomLogAppender* state;
|
|
||||||
it may include *SharedLogState* handles. The state returned by the factory may
|
|
||||||
contain independently created references and closures. State lasts for that
|
|
||||||
clone's lifetime; configuration refresh may replace it. A factory that raises
|
|
||||||
is retried on the next message, and errors go to the configured error handler.
|
|
||||||
Do not retain managed references from an incoming *LogMessage* for use in
|
|
||||||
another thread.
|
|
||||||
|
|
||||||
## Notes on Use in Multi-Threaded Applications
|
## Notes on Use in Multi-Threaded Applications
|
||||||
|
|
||||||
This library is intended to support thread-safe logging in multi-threaded
|
The loggers and appenders in this library are thread-safe and behaves more
|
||||||
applications, and hopefully to behave more intuitively in a multi-threaded
|
intuitively in a multi-threaded environment than `std/logging`, particularly in
|
||||||
environment than [std/logging][std-logging] while presenting a similar API. A
|
environments where the logging setup code may be separated from the
|
||||||
key difference is that logging setup can happen separately from thread
|
thread-management code (in an HTTP server, for example).
|
||||||
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
|
The *LogService* object is the main entry point for the logging system and
|
||||||
should be initialized via *initLogService* during application setup, usually on
|
should be initialized on the main thread. The *LogService* contains the "source
|
||||||
the main thread. Pass a copy of that *LogService* to each worker that needs
|
of truth" for logging configuration and is shared between all threads.
|
||||||
logging. Such copies use the same logging configuration and will be updated
|
Internally all access to the *LogService* is protected by a mutex.
|
||||||
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*,
|
Logging can be very noisy and if the *LogService* needed to be consulted for
|
||||||
then use its *getLogger* method to create loggers. Keep those local services and
|
every log event, it could easily become a performance bottleneck. To avoid
|
||||||
loggers within the thread that created them. If the main thread also logs,
|
this, the *getLogger* procedure makes a thread-local copy of the logging system
|
||||||
create a local service and loggers there too. Appenders configured during setup
|
configuration (loggers defined and appenders attached).
|
||||||
are available to each thread without repeating that setup in every worker.
|
|
||||||
|
|
||||||
Once workers have their own copies of the *LogService*, the original service
|
**Note** that this means that the thread-local cache of the logging system
|
||||||
can go out of scope and the thread that initialized it can finish. Logging
|
configuration can become stale if the logging system configuration is changed
|
||||||
remains available while any service copy, local service, or logger using that
|
after the thread-local copy is made (if another appender is added, for
|
||||||
service remains alive. Join worker threads before exiting the application so
|
example). This is a trade-off to avoid the performance penalty of consulting
|
||||||
they have an opportunity to finish logging.
|
the *LogService* for every log event.
|
||||||
|
|
||||||
When background writers are enabled with `-d:multithreaded`, normal application
|
This thread-local caching mechanism is the primary advantage of this logging
|
||||||
exit drains the console and file queues and waits for the writers to finish.
|
system over `std/logging` in a multi-threaded environment as it means that
|
||||||
No explicit flush or delay is needed after joining the threads that log.
|
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
|
If you find yourself needing to change the logging configuration after the
|
||||||
in any thread. Those changes are intended to take effect automatically on
|
logging system has been initialized, the *reloadThreadState* procedure can be
|
||||||
subsequent logging calls in every thread using that service, without recreating
|
used to update the thread-local cache of the logging system configuration, but
|
||||||
loggers or configuring each worker separately. `isEnabled` intentionally does
|
it must be called on the thread you wish to update.
|
||||||
not refresh configuration; see [Avoiding Expensive Log Preparation](#avoiding-expensive-log-preparation).
|
|
||||||
|
|
||||||
> [!NOTE]
|
As a final note, the advice to initialize the *LogService* on the main thread
|
||||||
> Thread-safety work is still in progress. Custom state and captured
|
is primarily to simplify the configuration of the logging service and avoid the
|
||||||
> formatters must follow the ownership rules above.
|
need to manually reload caches on individual threads. A *LogService* reference
|
||||||
> Nim 2.2.10 produces sanitizer reports in its default allocator
|
is required to call *getLogger*, but it can be created on any thread.
|
||||||
> during some cross-thread allocation patterns. See
|
|
||||||
> [the regression tests](tests/README.md) for the remaining work.
|
|
||||||
|
|
||||||
|
## Custom Appender Implementations
|
||||||
|
|
||||||
## Architectural Design
|
Due to the thread-safety of the logging system, there are a few additional
|
||||||
|
considerations when implementing custom appenders. The *LogAppender* abstract
|
||||||
|
class is the base class for all appenders. To implement a custom appender, two
|
||||||
|
methods must be implemented:
|
||||||
|
|
||||||
### Overview
|
### `appendLogMessage`
|
||||||
|
|
||||||
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
|
```nim
|
||||||
let handle = localLogSvc.service
|
method appendLogMessage*(appender: CustomLogAppender, msg: LogMessage): void {.base, gcsafe.}
|
||||||
# Pass handle to a worker, which calls handle.threadLocalRef() itself.
|
|
||||||
```
|
```
|
||||||
|
|
||||||
Configuration methods remain available on both types. Shared handles contain no
|
This is the primary appender implementation that takes a LogMessage and
|
||||||
cache; `handle.appenders()` clones the current shared configuration.
|
writes it to the appender's destination. As the signature suggests, the
|
||||||
`ensureFreshness` applies only to *ThreadLocalLogService*, which maintains a
|
implementation must be GC-safe. As a multi-method, the *CustomLogAppender* type
|
||||||
per-thread cache. Calls to `ensureFreshness(handle)` must be removed or changed
|
should be replaced by the actual name of your custom appender.
|
||||||
to refresh the relevant local service when migrating to version 3.0.0.
|
|
||||||
|
|
||||||
*ThreadLocalLogService* is the object that users are expected to interact with
|
Because the *LogAppender* uses multi-methods for dynamic dispatch, the
|
||||||
during regular operation and support both the configuration functions of
|
custom appender class must also be a `ref` type.
|
||||||
*LogService* and the creation of *Logger* objects.
|
|
||||||
|
|
||||||
> [!CAUTION]
|
### `initThreadCopy`
|
||||||
> *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. Built-in custom appenders copy
|
|
||||||
checked value state or shared-state handles. Factory appenders and formatters
|
|
||||||
copy value seeds and create their managed state lazily within the thread that
|
|
||||||
uses each clone. The state of an already-used clone is never copied into
|
|
||||||
another clone.
|
|
||||||
|
|
||||||
### 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
|
```nim
|
||||||
proc ensureFreshness*(ls: ThreadLocalLogService) =
|
method initThreadCopy*(app: LogAppender): LogAppender {.base, gcsafe.}
|
||||||
# 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:
|
|
||||||
let version = ls.shared.configVersion.load()
|
|
||||||
# Build the complete replacement cache, then install it after success.
|
|
||||||
# If building raises, preserve the previous cache and version for retry.
|
|
||||||
ls.configVersion = version
|
|
||||||
```
|
```
|
||||||
|
|
||||||
Goals/Motivation:
|
This method is used to create a thread-local copy of the appender. It is called
|
||||||
- Most logging operations skip expensive synchronization so the hot path is
|
by the *reloadThreadState* procedure to update the thread-local cache of the
|
||||||
fast.
|
logging system configuration. The implementation will be passed the appender
|
||||||
- Propogate changes automatically so all threads see configuration updates.
|
instance that was provided to the *addAppender* procedure and must return a
|
||||||
- Minimize lock contention by only acquiring when configuration changes
|
thread-local copy of that appender.
|
||||||
|
|
||||||
#### Thread-Local Caching
|
The `initThreadCopy` implementations for the built-in *ConsoleLogAppender* and
|
||||||
|
*FileLogAppender* provide simple examples of how to implement this method by
|
||||||
|
simply copying state into the local thread, but this method can also be used
|
||||||
|
to perform any other thread-specific initialization that may be required for
|
||||||
|
the appender implementation.
|
||||||
|
|
||||||
Each thread maintains its own copy of the logging configuration in
|
### Example Custom Appender
|
||||||
*ThreadLocalLogService*:
|
|
||||||
|
|
||||||
- **Appenders**: Thread-local copies created via `clone()` method
|
The following defines a simple custom appender that writes log messages to a
|
||||||
- **Thresholds**: Complete copy of namespace-to-level mappings
|
database table. It uses the [waterpark][] connection pooling library to manage
|
||||||
- **Version tracking**: Local version number for change detection
|
database connections as waterpark is also thread-safe and makes implementation
|
||||||
|
straight-forward.
|
||||||
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
|
```nim
|
||||||
type ErrorHandlerFunc* = proc(error: ref Exception, msg: string) {.gcsafe, nimcall.}
|
import db_connectors/db_postgres
|
||||||
|
import namespaced_logging, waterpark, waterpark/db_postgres
|
||||||
|
|
||||||
|
type DbLogAppender = ref object of LogAppender
|
||||||
|
dbPool: PostgresPool
|
||||||
|
|
||||||
|
let dbPool: PostgresPool = newPostgresPool(10, "", "", "", connectionString)
|
||||||
|
|
||||||
|
method initThreadCopy*(app: LogAppender): LogAppender =
|
||||||
|
result = DbLogAppender(dbPool: dbPool) # copy semantics as PostgresPool is an object
|
||||||
|
|
||||||
|
method appendLogMessage*(appender: DbLogAppender, msg: LogMessage): void {gcsafe.} =
|
||||||
|
appender.withConnection conn:
|
||||||
|
conn.insert(
|
||||||
|
"INSERT INTO log_events " &
|
||||||
|
" (level, scope, message, error, timestamp, custom_fields) " &
|
||||||
|
"VALUES " &
|
||||||
|
" (?, ?, ?, ?, ?, ?)",
|
||||||
|
msg.level,
|
||||||
|
msg.scope,
|
||||||
|
msg.message,
|
||||||
|
if msg.error.isSome: msg.error.msg
|
||||||
|
else: "",
|
||||||
|
msg.timestamp,
|
||||||
|
msg.additionalData)
|
||||||
```
|
```
|
||||||
|
|
||||||
### 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 enabled 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`.
|
|
||||||
Two scenarios that expose a known Nim allocator race are temporarily skipped
|
|
||||||
by default. Enable them with `NSL_TEST_RUNTIME_ALLOCATOR=1 nimble testThreadSafety`.
|
|
||||||
See [tests/README.md](tests/README.md) for commands, requirements, and coverage
|
|
||||||
limitations.
|
|
||||||
|
|
||||||
[log4j]: https://logging.apache.org/log4j/2.x/
|
[log4j]: https://logging.apache.org/log4j/2.x/
|
||||||
[logback]: https://logback.qos.ch/
|
[logback]: https://logback.qos.ch/
|
||||||
[effective logging level]: https://logback.qos.ch/manual/architecture.html#effectiveLevel
|
[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
|
|
||||||
@@ -1,4 +0,0 @@
|
|||||||
# begin Nimble config (version 2)
|
|
||||||
when withDir(thisDir(), system.fileExists("nimble.paths")):
|
|
||||||
include "nimble.paths"
|
|
||||||
# end Nimble config
|
|
||||||
@@ -1,6 +1,6 @@
|
|||||||
# Package
|
# Package
|
||||||
|
|
||||||
version = "3.0.0"
|
version = "2.0.0"
|
||||||
author = "Jonathan Bernard"
|
author = "Jonathan Bernard"
|
||||||
description = "Wrapper around std/logging to provide namespaced logging."
|
description = "Wrapper around std/logging to provide namespaced logging."
|
||||||
license = "MIT"
|
license = "MIT"
|
||||||
@@ -13,59 +13,3 @@ requires @["nim >= 2.2.0", "zero_functional"]
|
|||||||
|
|
||||||
# from https://git.jdb-software.com/jdb/nim-packages
|
# from https://git.jdb-software.com/jdb/nim-packages
|
||||||
requires "timeutils"
|
requires "timeutils"
|
||||||
|
|
||||||
proc runUnitTests() =
|
|
||||||
if fileExists("src/namespaced_logging.out"): rmFile("src/namespaced_logging.out")
|
|
||||||
exec "nimble c --mm:orc --threads:on src/namespaced_logging.nim"
|
|
||||||
if not fileExists("src/namespaced_logging.out"):
|
|
||||||
raise newException(OSError, "Unit test compilation produced no executable")
|
|
||||||
exec "src/namespaced_logging.out"
|
|
||||||
|
|
||||||
proc runRegressionTests() =
|
|
||||||
if fileExists("tests/bin/writer_child"): rmFile("tests/bin/writer_child")
|
|
||||||
if fileExists("tests/bin/regressions"): rmFile("tests/bin/regressions")
|
|
||||||
exec "nimble c --mm:orc --threads:on -d:multithreaded --out:tests/bin/writer_child tests/writer_child.nim"
|
|
||||||
if not fileExists("tests/bin/writer_child"):
|
|
||||||
raise newException(OSError, "Writer test compilation produced no executable")
|
|
||||||
exec "nimble c --mm:orc --threads:on --out:tests/bin/regressions tests/regressions.nim"
|
|
||||||
if not fileExists("tests/bin/regressions"):
|
|
||||||
raise newException(OSError, "Regression test compilation produced no executable")
|
|
||||||
exec "tests/bin/regressions"
|
|
||||||
|
|
||||||
proc runThreadSafetyTests() =
|
|
||||||
if fileExists("tests/bin/thread_safety"): rmFile("tests/bin/thread_safety")
|
|
||||||
if fileExists("tests/bin/writer_lifecycle"): rmFile("tests/bin/writer_lifecycle")
|
|
||||||
exec "nimble c --mm:orc --threads:on --passC:-fsanitize=thread --passC:-g --passL:-fsanitize=thread --out:tests/bin/thread_safety tests/thread_safety.nim"
|
|
||||||
if not fileExists("tests/bin/thread_safety"):
|
|
||||||
raise newException(OSError, "Thread-safety test compilation produced no executable")
|
|
||||||
exec "nimble c --mm:orc --threads:on --passC:-fsanitize=thread --passC:-g --passL:-fsanitize=thread --out:tests/bin/writer_lifecycle src/namespaced_logging.nim"
|
|
||||||
if not fileExists("tests/bin/writer_lifecycle"):
|
|
||||||
raise newException(OSError, "Writer lifecycle test compilation produced no executable")
|
|
||||||
exec "bash tests/run_tsan.sh tests/bin/thread_safety tests/bin/writer_lifecycle"
|
|
||||||
|
|
||||||
task test, "Run all enabled tests, including ThreadSanitizer, and report all failing suites.":
|
|
||||||
var failedSuites: seq[string] = @[]
|
|
||||||
template runSuite(name: string, action: untyped) =
|
|
||||||
echo "Running test suite: ", name
|
|
||||||
try:
|
|
||||||
action
|
|
||||||
echo "PASS: ", name
|
|
||||||
except OSError as err:
|
|
||||||
echo "FAIL: ", name, ": ", err.msg
|
|
||||||
failedSuites.add(name)
|
|
||||||
|
|
||||||
runSuite("unit", runUnitTests())
|
|
||||||
runSuite("regression", runRegressionTests())
|
|
||||||
runSuite("thread safety", runThreadSafetyTests())
|
|
||||||
if failedSuites.len > 0:
|
|
||||||
echo "Failed test suites: ", failedSuites
|
|
||||||
quit(1)
|
|
||||||
|
|
||||||
task testUnit, "Run the existing embedded unit tests under ORC.":
|
|
||||||
runUnitTests()
|
|
||||||
|
|
||||||
task testRegression, "Run ownership, configuration, and shutdown regressions.":
|
|
||||||
runRegressionTests()
|
|
||||||
|
|
||||||
task testThreadSafety, "Run ORC ownership tests with ThreadSanitizer (Linux).":
|
|
||||||
runThreadSafetyTests()
|
|
||||||
+380
-879
File diff suppressed because it is too large.
Load diff
@@ -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"
|
||||||
@@ -1,93 +0,0 @@
|
|||||||
## Ownership for custom logging state shared between threads under ORC.
|
|
||||||
import std/[atomics, locks, typetraits]
|
|
||||||
|
|
||||||
proc checkThreadValue[T]() =
|
|
||||||
when T is Lock or T is Cond or T is Atomic:
|
|
||||||
{.error: "Do not copy synchronization primitives as logging configuration".}
|
|
||||||
elif T is ref:
|
|
||||||
{.error: "Logging configuration cannot contain ref values; use a thread-local factory or SharedLogState with value data".}
|
|
||||||
elif T is string:
|
|
||||||
discard
|
|
||||||
elif T is seq:
|
|
||||||
checkThreadValue[typeof(default(T)[0])]()
|
|
||||||
elif T is array:
|
|
||||||
checkThreadValue[typeof(default(T)[low(T)])]()
|
|
||||||
elif T is object or T is tuple:
|
|
||||||
for field in fields(default(T)):
|
|
||||||
checkThreadValue[typeof(field)]()
|
|
||||||
elif supportsCopyMem(T):
|
|
||||||
discard
|
|
||||||
else:
|
|
||||||
{.error: "Logging configuration cannot contain closures; create them with a thread-local factory".}
|
|
||||||
|
|
||||||
template requireThreadValue*(T: typedesc) =
|
|
||||||
## Reject managed references and closures, including nested ones. Strings
|
|
||||||
## and sequences have value semantics under ORC. Raw pointers and custom
|
|
||||||
## copy hooks still require the caller's lifetime and synchronization contract.
|
|
||||||
## Type-check only: inspecting fields must not construct a payload at runtime.
|
|
||||||
when not compiles(block:
|
|
||||||
checkThreadValue[T]()
|
|
||||||
):
|
|
||||||
{.error: "Logging configuration must be value data without refs, closures, or synchronization primitives; use SharedLogState or a thread-local factory".}
|
|
||||||
|
|
||||||
type
|
|
||||||
SharedLogStateData[T] = object
|
|
||||||
owners: Atomic[int]
|
|
||||||
lock: Lock
|
|
||||||
value: T
|
|
||||||
|
|
||||||
SharedLogState*[T] = object
|
|
||||||
## Copyable owner of synchronized value data. Each thread owns its own
|
|
||||||
## handle. The payload cannot contain ordinary refs or captured closures.
|
|
||||||
data: ptr SharedLogStateData[T]
|
|
||||||
|
|
||||||
proc release[T](data: ptr SharedLogStateData[T]) =
|
|
||||||
if data != nil and data.owners.fetchSub(1, moAcquireRelease) == 1:
|
|
||||||
`=destroy`(data.value)
|
|
||||||
deinitLock(data.lock)
|
|
||||||
deallocShared(data)
|
|
||||||
|
|
||||||
proc `=destroy`*[T](state: SharedLogState[T]) = release(state.data)
|
|
||||||
|
|
||||||
proc `=copy`*[T](dest: var SharedLogState[T], source: SharedLogState[T]) =
|
|
||||||
if dest.data == source.data: return
|
|
||||||
if source.data != nil:
|
|
||||||
discard source.data.owners.fetchAdd(1, moRelaxed)
|
|
||||||
release(dest.data)
|
|
||||||
dest.data = source.data
|
|
||||||
|
|
||||||
proc `=dup`*[T](source: SharedLogState[T]): SharedLogState[T] =
|
|
||||||
if source.data != nil:
|
|
||||||
discard source.data.owners.fetchAdd(1, moRelaxed)
|
|
||||||
result.data = source.data
|
|
||||||
|
|
||||||
proc `=wasMoved`*[T](state: var SharedLogState[T]) = state.data = nil
|
|
||||||
|
|
||||||
proc initSharedLogState*[T](value: sink T): SharedLogState[T] =
|
|
||||||
requireThreadValue(T)
|
|
||||||
result.data = cast[ptr SharedLogStateData[T]](
|
|
||||||
allocShared0(sizeof(SharedLogStateData[T])))
|
|
||||||
result.data.owners.store(1)
|
|
||||||
initLock(result.data.lock)
|
|
||||||
result.data.value = value
|
|
||||||
|
|
||||||
proc withState*[T](state: SharedLogState[T],
|
|
||||||
action: proc(value: var T) {.gcsafe.}) =
|
|
||||||
## Execute synchronously under the state's lock. Do not retain a pointer to
|
|
||||||
## value or re-enter this same state from action. Exceptions release the lock.
|
|
||||||
if state.data == nil:
|
|
||||||
raise newException(ValueError, "SharedLogState is not initialized")
|
|
||||||
if action.isNil:
|
|
||||||
raise newException(ValueError, "SharedLogState callback is nil")
|
|
||||||
# The callback can release its caller's handle. Retain an explicit owner
|
|
||||||
# until after the lock is released; a borrowed parameter is insufficient.
|
|
||||||
let owner = `=dup`(state)
|
|
||||||
withLock owner.data.lock:
|
|
||||||
action(owner.data.value)
|
|
||||||
|
|
||||||
proc snapshot*[T](state: SharedLogState[T]): T =
|
|
||||||
## Return an independently owned value copy, made under the state's lock.
|
|
||||||
if state.data == nil:
|
|
||||||
raise newException(ValueError, "SharedLogState is not initialized")
|
|
||||||
withLock state.data.lock:
|
|
||||||
result = state.data.value
|
|
||||||
@@ -1,51 +1,42 @@
|
|||||||
import std/[json, options, syncio, os, times]
|
import std/[locks, sequtils, syncio, os, times]
|
||||||
from logging import Level
|
from logging import Level
|
||||||
from ../namespaced_logging import CustomLogAppender, initCustomLogAppender, LogMessage
|
from ../namespaced_logging import CustomLogAppender, initCustomLogAppender, LogMessage
|
||||||
import ./ownership
|
|
||||||
|
|
||||||
type
|
type
|
||||||
RecordedException* = object
|
LoggedMessages* = ref object
|
||||||
name*, msg*, stacktrace*: string
|
messages*: seq[LogMessage]
|
||||||
|
lock: Lock
|
||||||
RecordedLogMessage* = object
|
|
||||||
## A value snapshot: JSON is serialized, exceptions retain diagnostic text,
|
|
||||||
## and timestamps retain the instant without sharing a Timezone reference.
|
|
||||||
scope*: string
|
|
||||||
level*: Level
|
|
||||||
ts*: Time
|
|
||||||
msg*: string
|
|
||||||
err*: Option[RecordedException]
|
|
||||||
additionalData*: string
|
|
||||||
|
|
||||||
LoggedMessages* = SharedLogState[seq[RecordedLogMessage]]
|
|
||||||
|
|
||||||
proc initLoggedMessages*(): LoggedMessages =
|
proc initLoggedMessages*(): LoggedMessages =
|
||||||
initSharedLogState(newSeq[RecordedLogMessage]())
|
result = LoggedMessages(messages: @[])
|
||||||
|
initLock(result.lock)
|
||||||
|
|
||||||
|
|
||||||
proc add*(lm: LoggedMessages, msg: LogMessage) =
|
proc add*(lm: LoggedMessages, msg: LogMessage) =
|
||||||
var record = RecordedLogMessage(scope: msg.scope, level: msg.level,
|
withLock lm.lock: lm.messages.add(msg)
|
||||||
ts: msg.ts.toTime, msg: msg.msg,
|
|
||||||
additionalData: (if msg.additionalData.isNil: "null" else: $msg.additionalData))
|
|
||||||
if msg.err.isSome:
|
|
||||||
let err = msg.err.get
|
|
||||||
record.err = some(RecordedException(name: $err.name, msg: err.msg,
|
|
||||||
stacktrace: $err.trace))
|
|
||||||
lm.withState(proc(messages: var seq[RecordedLogMessage]) = messages.add(record))
|
|
||||||
|
|
||||||
proc clear*(lm: LoggedMessages) =
|
proc clear*(lm: LoggedMessages) =
|
||||||
lm.withState(proc(messages: var seq[RecordedLogMessage]) = messages.setLen(0))
|
withLock lm.lock: lm.messages = @[]
|
||||||
|
|
||||||
proc get*(lm: LoggedMessages): seq[RecordedLogMessage] = lm.snapshot()
|
|
||||||
|
|
||||||
proc testLogAppenderProc(state: var LoggedMessages, msg: LogMessage) {.gcsafe, noconv.} =
|
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)
|
state.add(msg)
|
||||||
|
|
||||||
proc initTestLogAppender*(
|
proc initTestLogAppender*(
|
||||||
lm: LoggedMessages,
|
lm: LoggedMessages,
|
||||||
namespace = "",
|
namespace = "",
|
||||||
threshold = lvlAll): CustomLogAppender[LoggedMessages] =
|
threshold = lvlAll): CustomLogAppender[LoggedMessages] =
|
||||||
initCustomLogAppender(state = lm, doLogMessage = testLogAppenderProc,
|
|
||||||
namespace = namespace, threshold = threshold)
|
initCustomLogAppender(
|
||||||
|
state = lm,
|
||||||
|
doLogMessage = testLogAppenderProc,
|
||||||
|
namespace = namespace,
|
||||||
|
threshold = threshold)
|
||||||
|
|
||||||
|
|
||||||
proc waitForFileContent*(
|
proc waitForFileContent*(
|
||||||
|
|||||||
-145
@@ -1,145 +0,0 @@
|
|||||||
# Regression tests
|
|
||||||
|
|
||||||
These tests assert the intended behavior. Enabled tests treat bugs as ordinary
|
|
||||||
failures. Two scenarios that expose a known Nim allocator race are temporarily
|
|
||||||
disabled by default; they remain available for explicit runs as described below.
|
|
||||||
|
|
||||||
Run from the repository root:
|
|
||||||
|
|
||||||
| Command | Coverage |
|
|
||||||
| --- | --- |
|
|
||||||
| `nimble test` | All enabled unit, regression, and ThreadSanitizer tests under ORC with threads enabled |
|
|
||||||
| `nimble testUnit` | Embedded unit tests, including writer submission/shutdown coordination |
|
|
||||||
| `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, formatter closures, collector snapshots, timestamps, and writer lifecycle, plus an independent-service control; factory-state and allocator scenarios are opt-in |
|
|
||||||
|
|
||||||
`factory-state` and `allocator` are reported as **SKIP** in normal runs because
|
|
||||||
they expose the default-allocator race in Nim 2.2.10. Resolving that runtime
|
|
||||||
issue is deferred. Their implementations and assertions remain intact, and
|
|
||||||
their test code is still compiled. To enable both scenarios:
|
|
||||||
|
|
||||||
```sh
|
|
||||||
NSL_TEST_RUNTIME_ALLOCATOR=1 nimble testThreadSafety
|
|
||||||
# Or include them in the full run:
|
|
||||||
NSL_TEST_RUNTIME_ALLOCATOR=1 nimble test
|
|
||||||
```
|
|
||||||
|
|
||||||
When enabled, their failures make the command fail normally. Skipping these
|
|
||||||
scenarios does not resolve the runtime limitation or establish that factory
|
|
||||||
state is fully validated under the default allocator.
|
|
||||||
|
|
||||||
`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.
|
|
||||||
The ownership tests do not need background I/O. The embedded writer lifecycle
|
|
||||||
tests call the internal writer functions directly; their sanitizer build is
|
|
||||||
`tests/bin/writer_lifecycle`.
|
|
||||||
|
|
||||||
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.
|
|
||||||
Each scenario runs separately so one failure does not hide another. To inspect
|
|
||||||
one scenario after building:
|
|
||||||
|
|
||||||
```sh
|
|
||||||
TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s tests/bin/thread_safety service
|
|
||||||
TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s tests/bin/writer_lifecycle 'Background writer lifecycle::*'
|
|
||||||
```
|
|
||||||
|
|
||||||
The worker start barrier ensures argument setup finishes before the concurrent
|
|
||||||
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.
|
|
||||||
`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 both `initLogMessage()` overloads and
|
|
||||||
structured JSON formatting concurrently. Generated timestamps use UTC, avoiding
|
|
||||||
the libc local-time conversion race previously reached via `std/times.now()`.
|
|
||||||
The timestamp regressions verify the captured instant, UTC timezone, and `Z`
|
|
||||||
suffix in structured output.
|
|
||||||
|
|
||||||
`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`. Normal runs retain the default allocator and skip the two
|
|
||||||
scenarios above. Sanitizer reports in any enabled scenario still fail the run;
|
|
||||||
there are no sanitizer suppressions.
|
|
||||||
|
|
||||||
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. `isEnabled` tests verify that namespace thresholds
|
|
||||||
remain cached until an explicit refresh, a logging call, or `getLogger`, while
|
|
||||||
the root fallback is read from shared state. This behavior is intentional so
|
|
||||||
guards can avoid configuration refresh work.
|
|
||||||
Refresh tests verify that repeated clone failures
|
|
||||||
preserve the old appenders and thresholds, release partial replacements, and
|
|
||||||
allow a later retry without another configuration change. A successful refresh
|
|
||||||
releases the replaced cache and installs both appenders and thresholds.
|
|
||||||
Shutdown tests launch
|
|
||||||
a fresh process for each scenario and check all 10,000 numbered messages after
|
|
||||||
normal exit, using isolated temporary paths and a 15-second deadline. Scenarios
|
|
||||||
cover stdout, stderr, files, empty formatted messages, multiple file destinations,
|
|
||||||
and four joined producers. They verify message content and order within each
|
|
||||||
producer and destination, using the real exit hook without sleeps or explicit
|
|
||||||
flushes. File batches must preserve blank records and finish their final batch
|
|
||||||
before the writer stops.
|
|
||||||
|
|
||||||
The embedded lifecycle tests start producers, release them to submit more
|
|
||||||
records while the file writer shuts down, and verify every accepted record.
|
|
||||||
They also check repeated shutdown, rejection of sends after shutdown, and
|
|
||||||
waking the console writer after an empty message. The sanitizer task runs these
|
|
||||||
tests as a separate process even when another scenario fails.
|
|
||||||
|
|
||||||
Nim 2.2.10's `Channel.close()` destroys its internal mutex while holding it,
|
|
||||||
which the lifecycle sanitizer test exposed after the writers had joined.
|
|
||||||
Shutdown therefore drains and joins the writers, rejects further submissions,
|
|
||||||
and leaves the process-wide channels allocated until process exit. It does not
|
|
||||||
call the faulty runtime teardown or suppress its diagnostics.
|
|
||||||
|
|
||||||
The suite provides targeted regressions; it does not exhaust thread scheduling
|
|
||||||
or ORC cycle-collector interleavings.
|
|
||||||
|
|
||||||
The ownership scenarios, lifetime suite, and appender-state cleanup regression
|
|
||||||
exercise the new ownership contracts. The known allocator issue remains
|
|
||||||
unresolved, with its failing scenarios temporarily disabled by default.
|
|
||||||
|
|
||||||
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.
|
|
||||||
@@ -1,170 +0,0 @@
|
|||||||
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
|
|
||||||
@@ -1,271 +0,0 @@
|
|||||||
import std/[json, os, osproc, strutils, tempfiles, times, unittest]
|
|
||||||
import ../src/namespaced_logging
|
|
||||||
import ./ownership
|
|
||||||
|
|
||||||
suite "Log message timestamps":
|
|
||||||
test "both constructors capture the current instant in UTC":
|
|
||||||
let before = getTime()
|
|
||||||
let textMessage = initLogMessage("timestamp", lvlInfo, "text")
|
|
||||||
let jsonMessage = initLogMessage("timestamp", lvlInfo, %*{"msg": "json"})
|
|
||||||
let after = getTime()
|
|
||||||
for message in [textMessage, jsonMessage]:
|
|
||||||
check message.ts.timezone.name == "Etc/UTC"
|
|
||||||
check message.ts.utcOffset == 0
|
|
||||||
check not message.ts.isDst
|
|
||||||
check message.ts.toTime >= before
|
|
||||||
check message.ts.toTime <= after
|
|
||||||
|
|
||||||
test "structured output represents generated timestamps in UTC":
|
|
||||||
for message in [initLogMessage("timestamp", lvlInfo, "text"),
|
|
||||||
initLogMessage("timestamp", lvlInfo, %*{"msg": "json"})]:
|
|
||||||
let encoded = parseJson(formatJsonStructuredLog(message))["ts"].getStr
|
|
||||||
check encoded == message.ts.format("yyyy-MM-dd'T'HH:mm:sszzz")
|
|
||||||
check encoded.endsWith("Z")
|
|
||||||
|
|
||||||
type
|
|
||||||
CloneControl = object
|
|
||||||
failNext: bool
|
|
||||||
FallibleAppender = ref object of LogAppender
|
|
||||||
control: ptr CloneControl
|
|
||||||
|
|
||||||
method clone(app: FallibleAppender): LogAppender {.gcsafe.} =
|
|
||||||
if app.control.failNext:
|
|
||||||
app.control.failNext = false
|
|
||||||
raise newException(ValueError, "injected clone failure")
|
|
||||||
FallibleAppender(control: app.control)
|
|
||||||
|
|
||||||
type
|
|
||||||
RefreshProbeObj = object of LogAppender
|
|
||||||
destroyed: ptr int
|
|
||||||
RefreshProbe = ref RefreshProbeObj
|
|
||||||
|
|
||||||
proc `=destroy`(app: RefreshProbeObj) =
|
|
||||||
if app.destroyed != nil: inc app.destroyed[]
|
|
||||||
`=destroy`(app.namespace)
|
|
||||||
|
|
||||||
method clone(app: RefreshProbe): LogAppender {.gcsafe.} =
|
|
||||||
RefreshProbe(namespace: app.namespace, destroyed: app.destroyed)
|
|
||||||
|
|
||||||
type
|
|
||||||
LifetimeProbeObj = object
|
|
||||||
destroyed: ptr int
|
|
||||||
LifetimeProbe = SharedLogState[LifetimeProbeObj]
|
|
||||||
|
|
||||||
proc `=destroy`(probe: LifetimeProbeObj) =
|
|
||||||
if probe.destroyed != nil:
|
|
||||||
inc probe.destroyed[]
|
|
||||||
|
|
||||||
proc ignoreMessage(state: var LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} =
|
|
||||||
discard
|
|
||||||
|
|
||||||
proc watchedService(destroyed: ptr int, namespace = ""): LogService =
|
|
||||||
result = initLogService()
|
|
||||||
result.addAppender(initCustomLogAppender(
|
|
||||||
initSharedLogState(LifetimeProbeObj(destroyed: destroyed)), ignoreMessage,
|
|
||||||
namespace = namespace))
|
|
||||||
|
|
||||||
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 uses cached namespace thresholds until a refresh":
|
|
||||||
var service = initLogService()
|
|
||||||
service.setThreshold("worker", lvlError)
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
let logger = local.getLogger("worker")
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
# Simulate a change from another service handle without introducing a
|
|
||||||
# reference-count race into this deterministic configuration test.
|
|
||||||
service.setThreshold("worker", lvlInfo)
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
local.ensureFreshness()
|
|
||||||
check logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
# A stale true result can become false when the logging call refreshes.
|
|
||||||
service.setThreshold("worker", lvlError)
|
|
||||||
check logger.isEnabled(lvlInfo)
|
|
||||||
logger.info("filtered after refreshing configuration")
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
# Creating another logger also refreshes their shared local service.
|
|
||||||
service.setThreshold("worker", lvlInfo)
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
discard local.getLogger("another")
|
|
||||||
check logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
test "isEnabled reads the shared root fallback without refreshing namespaces":
|
|
||||||
var service = initLogService(rootLevel = lvlError)
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
let logger = local.getLogger("worker")
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
service.setRootThreshold(lvlInfo)
|
|
||||||
service.setThreshold("worker", lvlError)
|
|
||||||
check logger.isEnabled(lvlInfo)
|
|
||||||
local.ensureFreshness()
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
test "a failed refresh is retried without another configuration change":
|
|
||||||
var control: CloneControl
|
|
||||||
var service = initLogService()
|
|
||||||
service.addAppender(FallibleAppender(control: addr control))
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
discard local.getLogger("worker")
|
|
||||||
service.setRootThreshold(lvlInfo)
|
|
||||||
|
|
||||||
control.failNext = true
|
|
||||||
expect ValueError:
|
|
||||||
local.ensureFreshness()
|
|
||||||
|
|
||||||
# clone now succeeds; the failed refresh must not have marked the
|
|
||||||
# incomplete local configuration as current.
|
|
||||||
local.ensureFreshness()
|
|
||||||
check local.appenders().len == 1
|
|
||||||
|
|
||||||
test "failed refresh preserves the old cache and releases partial replacements":
|
|
||||||
var oldStateDestroyed, discardedClones: int
|
|
||||||
var control: CloneControl
|
|
||||||
var service = watchedService(addr oldStateDestroyed, "old")
|
|
||||||
service.setThreshold("worker", lvlError)
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
let logger = local.getLogger("worker")
|
|
||||||
|
|
||||||
# Only the local cache retains the old appender's state after this change.
|
|
||||||
service.clearAppenders()
|
|
||||||
service.addAppender(RefreshProbe(namespace: "new", destroyed: addr discardedClones))
|
|
||||||
service.addAppender(FallibleAppender(control: addr control))
|
|
||||||
service.setThreshold("worker", lvlInfo)
|
|
||||||
let initiallyDestroyed = discardedClones
|
|
||||||
|
|
||||||
for attempt in 1 .. 2:
|
|
||||||
control.failNext = true
|
|
||||||
expect ValueError:
|
|
||||||
local.ensureFreshness()
|
|
||||||
check oldStateDestroyed == 0
|
|
||||||
check discardedClones == initiallyDestroyed + attempt
|
|
||||||
block:
|
|
||||||
let cached = local.appenders()
|
|
||||||
require cached.len == 1
|
|
||||||
check cached[0].namespace == "old"
|
|
||||||
check not logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
# No further configuration update is needed to retry and install both
|
|
||||||
# the new appenders and the new namespace thresholds.
|
|
||||||
local.ensureFreshness()
|
|
||||||
check oldStateDestroyed == 1
|
|
||||||
let cached = local.appenders()
|
|
||||||
require cached.len == 2
|
|
||||||
check cached[0].namespace == "new"
|
|
||||||
check logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
test "releasing the service releases state owned by its appenders":
|
|
||||||
var destroyed = 0
|
|
||||||
createAndReleaseService(addr destroyed)
|
|
||||||
check destroyed == 1
|
|
||||||
|
|
||||||
suite "Background writer shutdown regressions":
|
|
||||||
for destination in ["file", "console", "stderr", "file-empty", "console-empty",
|
|
||||||
"files", "file-parallel", "console-parallel"]:
|
|
||||||
test destination & " writer drains accepted messages at normal process exit":
|
|
||||||
let directory = createTempDir("namespaced_logging_shutdown_", "")
|
|
||||||
let outputPath = directory / "messages.log"
|
|
||||||
defer: removeDir(directory)
|
|
||||||
|
|
||||||
let child = startProcess(parentDir(getAppFilename()) / "writer_child",
|
|
||||||
args = [destination, outputPath], options = {poParentStreams})
|
|
||||||
defer: close(child)
|
|
||||||
let exitCode = child.waitForExit(15_000)
|
|
||||||
if exitCode == -1:
|
|
||||||
child.kill()
|
|
||||||
discard child.waitForExit()
|
|
||||||
check exitCode == 0
|
|
||||||
require fileExists(outputPath)
|
|
||||||
|
|
||||||
if destination.endsWith("-parallel"):
|
|
||||||
let received = readFile(outputPath).splitLines()
|
|
||||||
require received.len == 10_001
|
|
||||||
var next = [0, 2_500, 5_000, 7_500]
|
|
||||||
for line in received[0 ..< 10_000]:
|
|
||||||
require line.startsWith("message ")
|
|
||||||
let number = parseInt(line[8 .. ^1])
|
|
||||||
require number in 0 ..< 10_000
|
|
||||||
let worker = number div 2_500
|
|
||||||
check number == next[worker]
|
|
||||||
inc next[worker]
|
|
||||||
check next == [2_500, 5_000, 7_500, 10_000]
|
|
||||||
else:
|
|
||||||
var expected: string
|
|
||||||
for i in 0 ..< 10_000:
|
|
||||||
if destination == "file-empty" and i mod 128 == 0:
|
|
||||||
expected.add("\n")
|
|
||||||
expected.add("message " & $i & "\n")
|
|
||||||
check readFile(outputPath) == expected
|
|
||||||
if destination == "files":
|
|
||||||
require fileExists(outputPath & ".second")
|
|
||||||
check readFile(outputPath & ".second") == expected
|
|
||||||
@@ -1,36 +0,0 @@
|
|||||||
#!/usr/bin/env bash
|
|
||||||
set -u
|
|
||||||
|
|
||||||
binary=${1:?Expected the ThreadSanitizer test executable}
|
|
||||||
writer_binary=${2:?Expected the writer lifecycle test executable}
|
|
||||||
result=0
|
|
||||||
for scenario in independent service service-lifetime service-reconfigure custom-state formatter shared-state-lifetime factory-state collector formatter-lifetime timestamp allocator; do
|
|
||||||
# These scenarios expose Nim 2.2.10's default-allocator race independently
|
|
||||||
# of logging ownership. Keep them available while the runtime fix is deferred.
|
|
||||||
case "$scenario" in
|
|
||||||
factory-state|allocator)
|
|
||||||
if [[ ${NSL_TEST_RUNTIME_ALLOCATOR:-0} != 1 ]]; then
|
|
||||||
echo "SKIP: $scenario (known Nim allocator race; set NSL_TEST_RUNTIME_ALLOCATOR=1 to enable)"
|
|
||||||
continue
|
|
||||||
fi
|
|
||||||
;;
|
|
||||||
esac
|
|
||||||
echo "ThreadSanitizer scenario: $scenario"
|
|
||||||
if TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s "$binary" "$scenario"; then
|
|
||||||
echo "PASS: $scenario"
|
|
||||||
else
|
|
||||||
code=$?
|
|
||||||
echo "FAIL: $scenario (exit $code)" >&2
|
|
||||||
result=1
|
|
||||||
fi
|
|
||||||
done
|
|
||||||
|
|
||||||
echo "ThreadSanitizer scenario: writer-lifecycle"
|
|
||||||
if TSAN_OPTIONS=halt_on_error=1:exitcode=66 timeout 30s "$writer_binary" 'Background writer lifecycle::*'; then
|
|
||||||
echo "PASS: writer-lifecycle"
|
|
||||||
else
|
|
||||||
code=$?
|
|
||||||
echo "FAIL: writer-lifecycle (exit $code)" >&2
|
|
||||||
result=1
|
|
||||||
fi
|
|
||||||
exit "$result"
|
|
||||||
@@ -1,38 +0,0 @@
|
|||||||
## 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()
|
|
||||||
@@ -1,343 +0,0 @@
|
|||||||
## 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, 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]
|
|
||||||
|
|
||||||
proc awaitStart() =
|
|
||||||
while not start.load():
|
|
||||||
discard
|
|
||||||
|
|
||||||
proc serviceWorker(service: LogService) {.thread.} =
|
|
||||||
awaitStart()
|
|
||||||
for i in 0 ..< iterations:
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
let logger = local.getLogger("worker")
|
|
||||||
doAssert logger.isEnabled(lvlInfo)
|
|
||||||
|
|
||||||
proc independentWorker() {.thread.} =
|
|
||||||
awaitStart()
|
|
||||||
var service = initLogService()
|
|
||||||
service.setThreshold("worker", lvlInfo)
|
|
||||||
for i in 0 ..< iterations:
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
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 = object
|
|
||||||
value: int
|
|
||||||
StatefulAppender = CustomLogAppender[SharedLogState[CustomState]]
|
|
||||||
|
|
||||||
proc ignoreMessage(state: var SharedLogState[CustomState], msg: LogMessage) {.gcsafe, noconv.} =
|
|
||||||
discard
|
|
||||||
|
|
||||||
proc stateWorker(source: ptr StatefulAppender) {.thread.} =
|
|
||||||
awaitStart()
|
|
||||||
for i in 0 ..< iterations:
|
|
||||||
var copied: StatefulAppender
|
|
||||||
withLock cloneLock:
|
|
||||||
copied = StatefulAppender(clone(source[]))
|
|
||||||
doAssert copied.state.snapshot().value == 42
|
|
||||||
|
|
||||||
proc makeFormatter(prefix: string): StatefulLogFormatterFunc =
|
|
||||||
result = proc(msg: LogMessage): string {.gcsafe.} = prefix & msg.msg
|
|
||||||
|
|
||||||
proc formatterWorker(source: ptr ConsoleLogAppender) {.thread.} =
|
|
||||||
awaitStart()
|
|
||||||
# This formatter only needs msg. Avoid clock/timezone initialization so
|
|
||||||
# sanitizer diagnostics identify closure ownership rather than libc state.
|
|
||||||
let msg = LogMessage(msg: "message")
|
|
||||||
for i in 0 ..< iterations:
|
|
||||||
var copied: ConsoleLogAppender
|
|
||||||
withLock cloneLock:
|
|
||||||
copied = ConsoleLogAppender(clone(source[]))
|
|
||||||
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:
|
|
||||||
for msg in [initLogMessage("worker", lvlInfo, "message"),
|
|
||||||
initLogMessage("worker", lvlInfo, %*{"msg": "message"})]:
|
|
||||||
doAssert msg.msg == "message"
|
|
||||||
doAssert msg.ts.timezone.name == "Etc/UTC"
|
|
||||||
doAssert msg.ts.utcOffset == 0
|
|
||||||
doAssert not msg.ts.isDst
|
|
||||||
doAssert parseJson(formatJsonStructuredLog(msg))["ts"].getStr.len > 0
|
|
||||||
|
|
||||||
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
|
|
||||||
initLock(cloneLock)
|
|
||||||
defer: deinitLock(cloneLock)
|
|
||||||
case paramStr(1)
|
|
||||||
of "independent":
|
|
||||||
var workers: array[4, Thread[void]]
|
|
||||||
for i in 0 ..< workers.len:
|
|
||||||
createThread(workers[i], independentWorker)
|
|
||||||
start.store(true)
|
|
||||||
joinThreads(workers)
|
|
||||||
of "service":
|
|
||||||
var service = initLogService()
|
|
||||||
service.setThreshold("worker", lvlInfo)
|
|
||||||
service.addAppender(initConsoleLogAppender())
|
|
||||||
var workers: array[4, Thread[LogService]]
|
|
||||||
for i in 0 ..< workers.len:
|
|
||||||
createThread(workers[i], serviceWorker, service)
|
|
||||||
# No parent-side copying/configuration changes overlap the workers.
|
|
||||||
# The parent retains service and all thread argument storage until join.
|
|
||||||
start.store(true)
|
|
||||||
joinThreads(workers)
|
|
||||||
of "custom-state":
|
|
||||||
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)
|
|
||||||
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 = 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")
|
|
||||||
|
|
||||||
# The pointer-based scenarios borrow immutable source appenders whose owner
|
|
||||||
# outlives all workers. This isolates clone/destruction races from LogService
|
|
||||||
# copying and from ordinary unsynchronized application-state mutation.
|
|
||||||
main()
|
|
||||||
@@ -1,62 +0,0 @@
|
|||||||
import std/[os, strutils]
|
|
||||||
import ../src/namespaced_logging
|
|
||||||
|
|
||||||
when not defined(multithreaded):
|
|
||||||
{.error: "Compile this fixture with -d:multithreaded to exercise writer threads".}
|
|
||||||
|
|
||||||
proc formatLine(msg: LogMessage): string {.gcsafe.} = msg.msg & "\n"
|
|
||||||
|
|
||||||
proc formatOptionalLine(msg: LogMessage): string {.gcsafe.} =
|
|
||||||
if msg.msg.len > 0: msg.msg & "\n" else: ""
|
|
||||||
|
|
||||||
proc writeMessages(args: tuple[service: LogService, worker: int]) {.thread.} =
|
|
||||||
let logger = args.service.threadLocalRef().getLogger("shutdown")
|
|
||||||
for i in 0 ..< 2_500:
|
|
||||||
logger.info("message " & $(args.worker * 2_500 + i))
|
|
||||||
|
|
||||||
proc main() =
|
|
||||||
doAssert paramCount() == 2
|
|
||||||
let destination = paramStr(1)
|
|
||||||
var service = initLogService()
|
|
||||||
case destination
|
|
||||||
of "file", "file-parallel", "file-empty":
|
|
||||||
service.addAppender(initFileLogAppender(paramStr(2)))
|
|
||||||
of "files":
|
|
||||||
service.addAppender(initFileLogAppender(paramStr(2), namespace = "first"))
|
|
||||||
service.addAppender(initFileLogAppender(paramStr(2) & ".second", namespace = "second"))
|
|
||||||
of "console", "console-parallel", "console-empty":
|
|
||||||
# Keep stdout open through the library's exit hook. Redirecting it to a
|
|
||||||
# file also prevents a full parent/child pipe from blocking the writer.
|
|
||||||
doAssert open(stdout, paramStr(2), fmWrite)
|
|
||||||
if destination == "console-empty":
|
|
||||||
service.addAppender(initConsoleLogAppender(formatter = formatOptionalLine))
|
|
||||||
else:
|
|
||||||
service.addAppender(initConsoleLogAppender(formatter = formatLine))
|
|
||||||
of "stderr":
|
|
||||||
doAssert open(stderr, paramStr(2), fmWrite)
|
|
||||||
service.addAppender(initConsoleLogAppender(useStderr = true, formatter = formatLine))
|
|
||||||
else:
|
|
||||||
raise newException(ValueError, "unknown writer destination")
|
|
||||||
|
|
||||||
if destination.endsWith("-parallel"):
|
|
||||||
var workers: array[4, Thread[tuple[service: LogService, worker: int]]]
|
|
||||||
for i in 0 ..< workers.len:
|
|
||||||
createThread(workers[i], writeMessages, (service, i))
|
|
||||||
joinThreads(workers)
|
|
||||||
else:
|
|
||||||
let local = service.threadLocalRef()
|
|
||||||
if destination == "files":
|
|
||||||
let first = local.getLogger("first")
|
|
||||||
let second = local.getLogger("second")
|
|
||||||
for i in 0 ..< 10_000:
|
|
||||||
first.info("message " & $i)
|
|
||||||
second.info("message " & $i)
|
|
||||||
else:
|
|
||||||
let logger = local.getLogger("shutdown")
|
|
||||||
for i in 0 ..< 10_000:
|
|
||||||
if destination.endsWith("-empty") and i mod 128 == 0:
|
|
||||||
logger.info("")
|
|
||||||
logger.info("message " & $i)
|
|
||||||
# No sleep or explicit flush: normal exit must preserve accepted messages.
|
|
||||||
|
|
||||||
main()
|
|
||||||
Reference in new issue
Block a user