From cd85501561b6d778b81c5c888053e37f76b6d6a7 Mon Sep 17 00:00:00 2001 From: Jonathan Bernard Date: Sat, 4 Jan 2025 21:27:37 -0600 Subject: [PATCH] Major refactor to better support multi-threading. See README for details. --- .gitignore | 1 + README.md | 182 ++++++++++++++++++++++ namespaced_logging.nimble | 7 +- src/namespaced_logging.nim | 306 +++++++++++++++++++++++++++++-------- tests/config.nims | 1 + tests/tests.nim | 303 ++++++++++++++++++++++++++++++++++++ 6 files changed, 737 insertions(+), 63 deletions(-) create mode 100644 README.md create mode 100644 tests/config.nims create mode 100644 tests/tests.nim diff --git a/.gitignore b/.gitignore index 27b4ec6..f021ac0 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ .*.sw? nimcache/ +tests/tests diff --git a/README.md b/README.md new file mode 100644 index 0000000..1d8c379 --- /dev/null +++ b/README.md @@ -0,0 +1,182 @@ +# Namespaced Logging for Nim + +`namespaced_logging` provides a logging framework similar to [log4j][] or +[logback][] for Nim. It has three main motivating features: +- Hierarchical, namespaced logging +- Safe and straightforward to use in multi-threaded applications. +- Native support for structured logging (old-style string logging is also + supported). + +## Getting Started + +Install the package from nimble: + +```bash +nimble install namespaced_logging +``` + +Then, in your application, you can use the logging system like so: + +```nim +import namespaced_logging + +# On the main thread +let logService = initLogService() +logService.addAppender(initConsoleAppender(LogLevel.INFO)) + +# On any thread, including the main thread +let logger = logService.getLogger("app/service/example") +logger.info("Log from the example service") + +# Only get logs at the WARN or higher level from the database module +let logger = logService.getLogger("app/database", threshold = some(Level.lvlWarn)) +logger.error("Database connection failed") +``` + +## Loggers and Appenders + +The logging system is composed of two main components: loggers and appenders. +Loggers are used to create log events, which are then passed to the appenders. +Appenders take log events and write them to some destination, such as the +console, a file, or a network socket. Appenders also have a logging level +threshold, which determines which log events are acted upon by the appender, +and, optionally, a namespace filter, which determines from which loggers the +appender accepts log events. + +### Heirarchical Logging and Namespaces + +Loggers are organized hierarchically, with the hierarchy defined by the logger +name. A logger with the name `app/service/example` is a child of the logger +with the name `app/service`. By default, appenders accept log events from all +loggers, but this can be restricted by setting a namespace filter on the +appender. An appender with a namespace set will accept log events from all +loggers with names that start with the namespace. For example, an appender with +the namespace `app` will accept log events from the loggers `app`, +`app/service`, and `app/service/example`, but not from `api/service`. + +The other impact of the logger heirarchy is in the effective logging level of +the logger. Any logger can have an explicit logging level set, but if it does +not, the effective logging level is inherited from ancestor loggers upwards in +the logger heirarchy. This pattern is explained in detail in the [logback +documentation][effective logging level] and applies in the same manner to +loggers in this library. + + +## Notes on Use in Multi-Threaded Applications + +The loggers and appenders in this library are thread-safe and behaves more +intuitively in a multi-threaded environment than `std/logging`, particularly in +environments where the logging setup code may be separated from the +thread-management code (in an HTTP server, for example). + +The *LogService* object is the main entry point for the logging system and +should be initialized on the main thread. The *LogService* contains the "source +of truth" for logging configuration and is shared between all threads. +Internally all access to the *LogService* is protected by a mutex. + +Logging can be very noisy and if the *LogService* needed to be consulted for +every log event, it could easily become a performance bottleneck. To avoid +this, the *getLogger* procedure makes a thread-local copy of the logging system +configuration (loggers defined and appenders attached). + +**Note** that this means that the thread-local cache of the logging system +configuration can become stale if the logging system configuration is changed +after the thread-local copy is made (if another appender is added, for +example). This is a trade-off to avoid the performance penalty of consulting +the *LogService* for every log event. + +This thread-local caching mechanism is the primary advantage of this logging +system over `std/logging` in a multi-threaded environment as it means that +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. + +If you find yourself needing to change the logging configuration after the +logging system has been initialized, the *reloadThreadState* procedure can be +used to update the thread-local cache of the logging system configuration, but +it must be called on the thread you wish to update. + +As a final note, the advice to initialize the *LogService* on the main thread +is primarily to simplify the configuration of the logging service and avoid the +need to manually reload caches on individual threads. A *LogService* reference +is required to call *getLogger*, but it can be created on any thread. + +## Custom Appender Implementations + +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: + +### `appendLogMessage` + +```nim +method appendLogMessage*(appender: CustomLogAppender, msg: LogMessage): void {.base, gcsafe.} +``` + +This is the primary appender implementation that takes a LogMessage and +writes it to the appender's destination. As the signature suggests, the +implementation must be GC-safe. As a multi-method, the *CustomLogAppender* type +should be replaced by the actual name of your custom appender. + +Because the *LogAppender* uses multi-methods for dynamic dispatch, the +custom appender class must also be a `ref` type. + +### `initThreadCopy` + +```nim +method initThreadCopy*(app: LogAppender): LogAppender {.base, gcsafe.} +``` + +This method is used to create a thread-local copy of the appender. It is called +by the *reloadThreadState* procedure to update the thread-local cache of the +logging system configuration. The implementation will be passed the appender +instance that was provided to the *addAppender* procedure and must return a +thread-local copy of that appender. + +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. + +### Example Custom Appender + +The following defines a simple custom appender that writes log messages to a +database table. It uses the [waterpark][] connection pooling library to manage +database connections as waterpark is also thread-safe and makes implementation +straight-forward. + +```nim +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) +``` + + + +[log4j]: https://logging.apache.org/log4j/2.x/ +[logback]: https://logback.qos.ch/ +[effective logging level]: https://logback.qos.ch/manual/architecture.html#effectiveLevel diff --git a/namespaced_logging.nimble b/namespaced_logging.nimble index cdd0ba2..e6800a6 100644 --- a/namespaced_logging.nimble +++ b/namespaced_logging.nimble @@ -1,6 +1,6 @@ # Package -version = "0.3.2" +version = "1.0.0" author = "Jonathan Bernard" description = "Wrapper around std/logging to provide namespaced logging." license = "MIT" @@ -9,4 +9,7 @@ srcDir = "src" # Dependencies -requires "nim >= 1.0.4" +requires @["nim >= 2.2.0", "zero_functional"] + +# from https://git.jdb-software.com/jdb/nim-packages +requires "timeutils" diff --git a/src/namespaced_logging.nim b/src/namespaced_logging.nim index 2ed8833..59d4a97 100644 --- a/src/namespaced_logging.nim +++ b/src/namespaced_logging.nim @@ -1,76 +1,260 @@ -import std/[logging, options, sequtils, strutils, tables] +import std/[algorithm, json, locks, options, sequtils, strutils, tables, times] +import timeutils, zero_functional -export logging +from logging import Level +export logging.Level type - LoggingNamespace* = ref object - name: string + LogService* = ptr LogServiceObj + ## Shareable pointer to the shared log service object. + + LogServiceObj = object + cfg: LogServiceConfig + lock: Lock + + LogServiceConfig = object + loggers: seq[LoggerConfig] + appenders: seq[LogAppender] + rootLevel: Level + + ThreadState = object + cfg: LogServiceConfig + loggers: TableRef[string, Logger] + + LoggerConfig* = object of RootObj + name*: string + threshold*: Option[Level] + + Logger* = object of LoggerConfig + svc: LogService + + LogAppender* = ref object of RootObj + ## Base type for log appenders. + namespace*: string + threshold*: Level + + LogMessage* = object + scope*: string level*: Level - msgPrefix*: string + error*: Option[ref Exception] + timestamp*: DateTime + message*: string + additionalData*: JsonNode -var knownNamespacesInst {.threadvar.}: TableRef[string, LoggingNamespace] + ConsoleLogAppender* = ref object of LogAppender + ## Log appender that writes log messages to the console. See + ## *initConsoleLogAppender* for a convenient way to create instances of + ## this appender. + formatter*: proc (msg: LogMessage): string {.gcsafe.} + ## Formatter allows for custom formatting of log messages. The default + ## formatter uses `formatJsonStructuredLog` to format log messages as + ## JSON objects which are then stringified before being written to the + ## console. + useStderr*: bool -template knownNamespaces(): TableRef[string, LoggingNamespace] = - if knownNamespacesInst == nil: - knownNamespacesInst = newTable[string, LoggingNamespace]() - knownNamespacesInst + #[ + # TODO: need to think throudh thread-safe IO for file logging + FileLogAppender* = ref object of LogAppender + file*: File + formatter*: proc (msg: LogMessage): string {.gcsafe.} + ]# -proc initLoggingNamespace( + +var threadState {.threadvar.}: ThreadState + + +method initThreadCopy*(app: LogAppender): LogAppender {.base, gcsafe.} = + raise newException(CatchableError, "missing concrete implementation") + + +method initThreadCopy*(cla: ConsoleLogAppender): LogAppender {.gcsafe.} = + result = ConsoleLogAppender( + namespace: cla.namespace, + threshold: cla.threshold, + formatter: cla.formatter, + useStderr: cla.useStdErr) + + +#[ +method initThreadCopy*(fla: FileLogAppender): LogAppender {.gcsafe.} = + result = FileLogAppender( + namespace: fla.namespace, + threshold: fla.threshold, + formatter: fla.formatter, + file: fla.file) +]# + + +func initLogger(svc: LogService, cfg: LoggerConfig): Logger = + result = Logger(name: cfg.name, threshold: cfg.threshold, svc: svc) + + +proc copyAppenders[T](s: seq[T]): seq[T] {.gcsafe.} = + for app in s: + result.add(initThreadCopy(app)) + + +proc reloadThreadState*(ls: LogService) {.gcsafe.} = + ## Refresh this thread's copy of the log service configuration. Note that + ## this currently loses any loggers defined on this thread since it was last + ## reloaded. + acquire(ls.lock) + # TODO: push loggers defined on this thread to the shared state? + threadState.cfg = ls.cfg + threadState.cfg.appenders = copyAppenders(ls.cfg.appenders) + release(ls.lock) + + let loggers = threadState.cfg.loggers --> map(initLogger(ls, it)) + threadState.loggers = newTable(loggers --> map((it.name, it))) + + +proc getThreadState(ls: LogService): ThreadState = + if threadState.loggers.isNil: reloadThreadState(ls) + return threadState + + +func `%`*(msg: LogMessage): JsonNode = + result = %*{ + "scope": msg.scope, + "level": msg.level, + "message": msg.message, + "timestamp": msg.timestamp.formatIso8601 + } + + if msg.error.isSome: + result["err"] = %($msg.error.get.name & ": " & msg.error.get.msg) + result["stacktrace"] = %($msg.error.get.trace) + + if msg.additionalData.kind == JObject: + for (k, v) in pairs(msg.additionalData): + if not result.hasKey(k): result[k] = v + + +proc initLogService*(rootLevel = lvlAll): LogService = + result = cast[LogService](allocShared0(sizeof(LogServiceObj))) + result.cfg.rootLevel = rootLevel + + +proc setRootLevel*(ls: LogService, lvl: Level) = + ls.cfg.rootLevel = lvl + + +func formatJsonStructuredLog*(msg: LogMessage): string {.gcsafe.} = return $(%msg) + + +func initConsoleLogAppender*( + namespace = "", + threshold = lvlInfo, + formatter = formatJsonStructuredLog, + useStderr = false): ConsoleLogAppender {.gcsafe.} = + result = ConsoleLogAppender( + namespace: namespace, + threshold: threshold, + formatter: formatter, + useStderr: useStdErr) + + +method appendLogMessage*(appender: LogAppender, msg: LogMessage): void {.base, gcsafe.} = + raise newException(CatchableError, "missing concrete implementation") + + +method appendLogMessage*(cla: ConsoleLogAppender, msg: LogMessage): void {.gcsafe.} = + if msg.level < cla.threshold: return + + let strMsg = formatJsonStructuredLog(msg) + if cla.useStderr: stderr.writeLine(strMsg) + else: stdout.writeLine(strMsg) + + +proc getLogger*( + ls: LogService, name: string, - level = lvlInfo, - msgPrefix: string - ): LoggingNamespace {.raises: [].} = + threshold = none[Level]()): Logger {.gcsafe.} = - result = LoggingNamespace( - name: name, - level: level, - msgPrefix: msgPrefix) + let ts = getThreadState(ls) + if not ts.loggers.contains(name): + ts.loggers[name] = Logger(name: name, threshold: threshold, svc: ls) + return ts.loggers[name] - knownNamespaces[name] = result -proc getLoggerForNamespace*( - namespace: string, - level = lvlInfo, - msgPrefix: Option[string] = none[string]() - ): LoggingNamespace {.raises: [].} = - ## Get a LogginNamesapce for the given namespace. The first time this is - ## called for a given name space a new logger will be created. In that case, - ## the optional `level` and `msgPrefix` will be used to configure the logger. - ## In all other cases, these paratmers are ignored and the existing namespace - ## instance is returned +proc addAppender*(ls: LogService, appender: LogAppender) {.gcsafe.} = + acquire(ls.lock) + ls.cfg.appenders.add(appender) + release(ls.lock) - if knownNamespaces.hasKey(namespace): - try: return knownNamespaces[namespace] - except KeyError: - try: error "namespaced_logging: Impossible error. " & - "knownNamespaces contains " & namespace & " but raised a KeyError " & - "trying to access it." - except: discard - else: - if msgPrefix.isSome: - return initLoggingNamespace(namespace, level, msgPrefix.get) - else: - return initLoggingNamespace(namespace, level, namespace & ": ") -proc setLevelForNamespace*(namespace: string, lvl: Level, recursive = false) {.raises: [] .} = - if recursive: - for k, v in knownNamespaces.pairs: - if k.startsWith(namespace): - v.level = lvl - else: getLoggerForNamespace(namespace).level = lvl +func `<`(a, b: LoggerConfig): bool = a.name < b.name -proc name*(ns: LoggingNamespace): string = ns.name -proc log*(ns: LoggingNamespace, level: Level, args: varargs[string, `$`]) {.raises: [] .} = - try: - if level >= ns.level: - if not ns.msgPrefix.isEmptyOrWhitespace: - log(level, args.mapIt(ns.msgPrefix & it)) - else: log(level, args) - except: discard -proc debug*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlDebug, args) -proc info*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlInfo, args) -proc notice*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlNotice, args) -proc warn*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlWarn, args) -proc error*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlError, args) -proc fatal*(ns: LoggingNamespace, args: varargs[string, `$`]) = log(ns, lvlFatal, args) +func getEffectiveLevel(ts: ThreadState, name: string): Level {.gcsafe.} = + result = ts.cfg.rootLevel + + var namespaces = toSeq(values(ts.loggers)) + namespaces = sorted( + namespaces --> filter(name.startsWith(it.name)), + SortOrder.Descending) + + for n in namespaces: + if n.threshold.isSome: + result = n.threshold.get + +proc doLog(logger: Logger, msg: LogMessage): void {.gcsafe.} = + let ts = getThreadState(logger.svc) + let threshold = + if logger.threshold.isSome: logger.threshold.get + else: getEffectiveLevel(ts, logger.name) + + if msg.level < threshold: return + + for app in ts.cfg.appenders: + if logger.name.startsWith(app.namespace): + appendLogMessage(app, msg) + + +proc log*(l: Logger, lvl: Level, msg: string) {.gcsafe.} = + l.doLog(LogMessage( + scope: l.name, + level: lvl, + error: none[ref Exception](), + timestamp: now(), + message: msg, + additionalData: newJNull())) + + +proc log*( + l: Logger, + lvl: Level, + error: ref Exception, + msg: string ) {.gcsafe.} = + l.doLog(LogMessage( + scope: l.name, + level: lvl, + error: some(error), + timestamp: now(), + message: msg, + additionalData: newJNull())) + +proc log*(l: Logger, lvl: Level, msg: JsonNode) {.gcsafe.} = + l.doLog(LogMessage( + scope: l.name, + level: lvl, + error: none[ref Exception](), + timestamp: now(), + message: + if msg.hasKey("msg"): msg["msg"].getStr + else: "", + additionalData: msg)) + + +template debug*[T](l: Logger, msg: T) = log(l, lvlDebug, msg) +template info*[T](l: Logger, msg: T) = log(l, lvlInfo, msg) +template notice*[T](l: Logger, msg: T) = log(l, lvlNotice, msg) +template warn*[T](l: Logger, msg: T) = log(l, lvlWarn, msg) + +template error*[T](l: Logger, msg: T) = log(l, lvlError, msg) +template error*(l: Logger, error: ref Exception, msg: string) = + log(l, lvlError, error, msg) + +template fatal*[T](l: Logger, msg: T) = log(l, lvlFatal, msg) +template fatal*(l: Logger, error: ref Exception, msg: string) = + log(l, lvlFatal, error, msg) diff --git a/tests/config.nims b/tests/config.nims new file mode 100644 index 0000000..a119208 --- /dev/null +++ b/tests/config.nims @@ -0,0 +1 @@ +--path:"../src" diff --git a/tests/tests.nim b/tests/tests.nim new file mode 100644 index 0000000..a24db03 --- /dev/null +++ b/tests/tests.nim @@ -0,0 +1,303 @@ +import std/[json, locks, options, strutils, unittest] +import namespaced_logging, zero_functional + + +type + TestLogAppender = ref object of LogAppender + statePtr: ptr TestLogState + + TestLogState = object + logs: seq[(string, LogMessage)] + lock: Lock + +var sharedTestLogState: ptr TestLogState + +proc initSharedTestLogState() = + sharedTestLogState = cast[ptr TestLogState](allocShared0(sizeof(TestLogState))) + sharedTestLogState.logs = @[] + +method appendLogMessage*(tla: TestLogAppender, msg: LogMessage): void {.gcsafe.} = + if msg.level < tla.threshold: return + acquire(sharedTestLogState.lock) + sharedTestLogState.logs.add((tla.namespace, msg)) + release(sharedTestLogState.lock) + +method initThreadCopy*(tla: TestLogAppender): LogAppender {.gcsafe.} = + TestLogAppender( + namespace: tla.namespace, + threshold: tla.threshold, + statePtr: tla.statePtr) + +proc initTestLogAppender(namespace = "", threshold = lvlAll): TestLogAppender = + TestLogAppender( + namespace: namespace, + threshold: threshold, + statePtr: sharedTestLogState) + +initSharedTestLogState() + +suite "initialization": + + test "can create LogService": + let logSvc = initLogService() + check: + not logSvc.isNil + + test "reloadThreadState": + let logSvc = initLogService() + reloadThreadState(logSvc) + + + test "create Logger": + let logSvc = initLogService() + let logger = logSvc.getLogger("test") + + check: + logger.threshold.isNone + logger.name == "test" + + test "create Logger with threshold": + let logSvc = initLogService() + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test", some(lvlDebug)) + + check: + logger.threshold.isSome + logger.threshold.get == lvlDebug + logger.name == "test" + + test "initConsoleLogAppender": + let cla = initConsoleLogAppender() + +suite "log methods": + + test "log with ConsoleLogAppender": + let logSvc = initLogService() + let cla = initConsoleLogAppender(threshold = lvlDebug) + let tla = initTestLogAppender() + logSvc.addAppender(cla) + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test") + logger.info("Test log message.") + + acquire(sharedTestLogState.lock) + check sharedTestLogState.logs.len == 1 + let log = sharedTestLogState.logs[0][1] + check: + log.message == "Test log message." + log.level == lvlInfo + log.scope == "test" + log.error.isNone + log.additionalData.kind == JNull + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "log with error": + let logSvc = initLogService() + let tla = initTestLogAppender() + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test") + logger.error(newException(Exception, "Test error message."), "exception occurred") + + acquire(sharedTestLogState.lock) + check sharedTestLogState.logs.len == 1 + let log = sharedTestLogState.logs[0][1] + check: + log.message == "exception occurred" + log.level == lvlError + log.scope == "test" + log.error.isSome + log.error.get.name == "Exception" + log.error.get.msg == "Test error message." + log.additionalData.kind == JNull + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + +suite "namespaces": + + test "appenders at the root level accept all messages": + let logSvc = initLogService() + let tla = initTestLogAppender() + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let l1 = logSvc.getLogger("") + let l2 = logSvc.getLogger("test") + let l3 = logSvc.getLogger("test/sub") + + l1.info("message from root") + l2.info("message from test") + l3.info("message from test/sub") + + acquire(sharedTestLogState.lock) + let logs = sharedTestLogState.logs + check: + logs.len == 3 + logs[0][1].message == "message from root" + logs[1][1].message == "message from test" + logs[2][1].message == "message from test/sub" + + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "appenders accept messages at their namespace": + let logSvc = initLogService() + let tla = initTestLogAppender(namespace = "test") + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test") + logger.info("message from test") + + acquire(sharedTestLogState.lock) + check: + sharedTestLogState.logs.len == 1 + sharedTestLogState.logs[0][0] == "test" + sharedTestLogState.logs[0][1].message == "message from test" + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "appenders accept messages from scopes within their namespace": + let logSvc = initLogService() + let tlaRoot = initTestLogAppender(namespace = "") + let tlaTest = initTestLogAppender(namespace = "test") + logSvc.addAppender(tlaRoot) + logSvc.addAppender(tlaTest) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test/sub") + logger.info("message from test/sub") + + acquire(sharedTestLogState.lock) + let logs = sharedTestLogState.logs + check: + logs.len == 2 + logs[0][0] == "" + logs[0][1].message == "message from test/sub" + logs[1][0] == "test" + logs[1][1].message == "message from test/sub" + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "appenders do not accept messages outside their namespace": + let logSvc = initLogService() + let tlaRoot = initTestLogAppender(namespace = "") + let tlaTest = initTestLogAppender(namespace = "test") + logSvc.addAppender(tlaRoot) + logSvc.addAppender(tlaTest) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("other") + logger.info("message from other") + + acquire(sharedTestLogState.lock) + let logs = sharedTestLogState.logs + check: + logs.len == 1 + logs[0][0] == "" + logs[0][1].message == "message from other" + + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + +suite "thresholds": + + test "logger gates messages by level": + let logSvc = initLogService() + let tla = initTestLogAppender() + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test", some(lvlInfo)) + logger.debug("message at debug level") + logger.info("message at info level") + logger.warn("message at warn level") + + acquire(sharedTestLogState.lock) + let logs = sharedTestLogState.logs + check: + logs.len == 2 + logs[0][1].message == "message at info level" + logs[1][1].message == "message at warn level" + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "root threshold applies when logger has none": + let logSvc = initLogService(lvlWarn) + let tla = initTestLogAppender() + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("test") + logger.debug("message at debug level") + logger.info("message at info level") + logger.warn("message at warn level") + + acquire(sharedTestLogState.lock) + let logs = sharedTestLogState.logs + check: + logs.len == 1 + logs[0][1].message == "message at warn level" + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "logger inherits effective threshold from ancestors": + let logSvc = initLogService() + let tla = initTestLogAppender() + logSvc.addAppender(tla) + reloadThreadState(logSvc) + + let l1 = logSvc.getLogger("test", some(lvlInfo)) + let l2 = logSvc.getLogger("test/sub") + let l3 = logSvc.getLogger("test/sub/subsub") + let l4 = logSvc.getLogger("other") + + l3.debug("message at debug level") + l3.info("message at info level") + l3.warn("message at warn level") + l4.debug("message at debug level") + + acquire(sharedTestLogState.lock) + let l3Logs = sharedTestLogState.logs --> filter(it[1].scope == "test/sub/subsub") + let l4Logs = sharedTestLogState.logs --> filter(it[1].scope == "other") + check: + l3Logs.len == 2 + l3Logs[0][1].message == "message at info level" + l3Logs[1][1].message == "message at warn level" + l4Logs.len == 1 + l4Logs[0][1].message == "message at debug level" + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock) + + test "appender gates messages by level": + let logSvc = initLogService() + let tlaInfo = initTestLogAppender(namespace="a", threshold = lvlInfo) + let tlaDebug = initTestLogAppender(namespace="a/b", threshold = lvlDebug) + logSvc.addAppender(tlaInfo) + logSvc.addAppender(tlaDebug) + reloadThreadState(logSvc) + + let logger = logSvc.getLogger("a/b") + logger.debug("message at debug level") + logger.info("message at info level") + logger.warn("message at warn level") + + acquire(sharedTestLogState.lock) + let aLogs = sharedTestLogState.logs --> filter(it[0] == "a") + let bLogs = sharedTestLogState.logs --> filter(it[0] == "a/b") + check: + aLogs.len == 2 + aLogs[0][1].message == "message at info level" + aLogs[1][1].message == "message at warn level" + bLogs.len == 3 + bLogs[0][1].message == "message at debug level" + bLogs[1][1].message == "message at info level" + bLogs[2][1].message == "message at warn level" + + sharedTestLogState.logs.setLen(0) + release(sharedTestLogState.lock)