import std/[algorithm, atomics, exitprocs, json, locks, options, paths, sequtils, strutils, tables, times] import timeutils import std/logging as stdlog import namespaced_logging/ownership export ownership from std/logging import Level export Level type SharedLogServiceState = object owners: Atomic[int] # Lifetime of independently owned service handles configVersion: Atomic[int] # To signal the need for threads to update lock: Lock # To protect reads/writes across threads appenders: seq[LogAppender] thresholds: Table[string, Level] rootLevel: Atomic[Level] errorHandler: ErrorHandlerFunc errorHandlerLock: Lock ErrorHandlerFunc* = proc (err: ref Exception, msg: string) {.gcsafe,nimcall.} LogService* = object ## Copyable shared configuration handle with an atomic lifetime. ## Each thread must own its own handle; do not concurrently assign to or ## destroy the same handle variable while another thread reads it. shared: ptr SharedLogServiceState ThreadLocalLogService* = ref object ## Cache confined to the thread that creates it. Appender clones must ## themselves respect thread ownership of custom state and formatters. serviceHandle: LogService configVersion: int appenders: seq[LogAppender] thresholds: TableRef[string, Level] Logger* = ref object scope*: string threadSvc: ThreadLocalLogService LogAppender* = ref object of RootObj ## Base type for log appenders. Note that all LogAppenders must have a ## clone method which must return an independently owned appender for ## shared configuration and for each thread's cache. Nested state and ## formatter references also need safe ownership; allocating a new outer ## appender alone does not make shared ORC references safe. namespace*: string ## Allows filtering of messages based on their scope. Messages are ## accepted if the Appender's namespace is prefix (or equal to) the ## message's scope. For example: ## ## - ns: `"api"`, scope: `"api/user"` --> processed ## - ns: `"api"`, scope: `"db/user"` --> ignored threshold*: Level ## Allows filtering based on message level. Appenders will process all ## messages whose levels are greater or equal to the appender's ## threshold. LogMessage* = object scope*: string level*: Level err*: Option[ref Exception] ts*: DateTime msg*: string additionalData*: JsonNode StatefulLogFormatterFunc* = proc (msg: LogMessage): string {.gcsafe.} StatelessLogFormatterFunc* = proc (msg: LogMessage): string {.gcsafe, nimcall.} LogFormatter* = ref object of RootObj ## Thread-confined formatter. clone must create independently owned state. StatelessLogFormatterImpl = ref object of LogFormatter callback: StatelessLogFormatterFunc FactoryLogFormatterImpl[S] = ref object of LogFormatter seed: S factory: proc(seed: S): StatefulLogFormatterFunc {.gcsafe, nimcall.} local: StatefulLogFormatterFunc ConsoleMessage = object stop: bool msg: string useStderr: bool FileMessage = object stop: bool msg: string absPath: Path LogWriterThreadState[M] = object lock: Lock initialized: bool shutdown: bool chan: Channel[M] writerThread: Thread[void] 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*: LogFormatter ## Formatter allows for custom formatting of log messages. The default ## formatter uses *formatSimpleTextLog* which just writes the log message. ## *formatJsonStructuredLog* is also provided to support writing logs out ## as structured JSON. useStderr*: bool CustomLogAppenderFunc*[T] = proc(state: var T, msg: LogMessage) {.gcsafe, noconv.} CustomLogAppender*[T] = ref object of LogAppender doLogMessage*: CustomLogAppenderFunc[T] state*: T FactoryCustomLogAppender*[S, T] = ref object of LogAppender ## Creates state lazily in the thread performing the first append. seed: S factory: proc(seed: S): T {.gcsafe, nimcall.} doLogMessage: CustomLogAppenderFunc[T] local: T initialized: bool FileLogAppender* = ref object of LogAppender formatter*: LogFormatter absPath*: Path StdLoggingAppender* = ref object of LogAppender ## Log appender that forwards log messages to the std/logging ## implementation. This is primarily intended for libraries and other ## situations where you expect that your code will be third-party to others ## and want to respect applications which use std/logging for log handlers ## and configuration. fallbackOnly*: bool ## when true, only forward to std/logging where there are no appenders ## configured on the related LogService formatter*: LogFormatter const UninitializedConfigVersion = low(int) proc retainSharedState(state: ptr SharedLogServiceState) {.inline.} = if state != nil: discard state.owners.fetchAdd(1, moRelaxed) proc releaseSharedState(state: ptr SharedLogServiceState) = if state != nil and state.owners.fetchSub(1, moAcquireRelease) == 1: # The last owner has exclusive access to the control block. Its managed # fields must be destroyed explicitly because it is manually allocated. `=destroy`(state.appenders) `=destroy`(state.thresholds) deinitLock(state.errorHandlerLock) deinitLock(state.lock) deallocShared(state) proc `=destroy`*(ls: LogService) = releaseSharedState(ls.shared) proc `=copy`*(dest: var LogService, source: LogService) = if dest.shared == source.shared: return retainSharedState(source.shared) releaseSharedState(dest.shared) dest.shared = source.shared proc `=dup`*(source: LogService): LogService = retainSharedState(source.shared) result.shared = source.shared proc `=wasMoved`*(ls: var LogService) = ls.shared = nil # The compiler-generated sink operation transfers the pointer after releasing # the destination. It does not retain the transferred owner. template shared(ls: ThreadLocalLogService): untyped = ls.serviceHandle.shared proc service*(ls: ThreadLocalLogService): LogService = ## Obtain an independently owned shared handle, e.g. to pass to a worker. ## This replaces copying ls[] when ThreadLocalLogService was ref LogService. ls.serviceHandle var consoleLogging {.global.}: LogWriterThreadState[ConsoleMessage] var fileLogging {.global.}: LogWriterThreadState[FileMessage] initLock(consoleLogging.lock) initLock(fileLogging.lock) proc initLogMessage*( scope: string, lvl: Level, msg: string, err: Option[ref Exception] = none[ref Exception](), additionalData: JsonNode = newJNull()): LogMessage = LogMessage( scope: scope, level: lvl, err: err, ts: now(), msg: msg, additionalData: additionalData) proc initLogMessage*( scope: string, lvl: Level, msg: JsonNode, err: Option[ref Exception] = none[ref Exception]()): LogMessage = LogMessage( scope: scope, level: lvl, err: err, ts: now(), msg: if msg.hasKey("msg"): msg["msg"].getStr elif msg.hasKey("message"): msg["message"].getStr else: "", additionalData: msg) method clone*(app: LogAppender): LogAppender {.base, gcsafe.} = raise newException(CatchableError, "missing concrete implementation") method appendLogMessage( appender: LogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.base, gcsafe.} = raise newException(CatchableError, "missing concrete implementation") proc defaultErrorHandlerFunc*( err: ref Exception, msg: string) {.gcsafe,nimcall.} = try: stderr.writeLine("LOGGING ERROR [" & msg & ": " & err.msg) stderr.writeLine($err.getStackTrace()) stderr.flushFile() except Exception: discard # we tried... proc shutdownWriter[M](state: var LogWriterThreadState[M]) = # Submission uses this same lock. The stop message follows all accepted # records, and no producer can submit after shutdown begins. withLock state.lock: if state.shutdown: return state.shutdown = true if not state.initialized: return state.chan.send(M(stop: true)) joinThread(state.writerThread) # These queues have process lifetime and cannot be restarted. Keep the # drained channel storage until process exit: Nim 2.2.10's Channel.close # destroys its internal mutex while holding it (a sanitizer failure). state.initialized = false proc shutdownThreadedConsoleLogging() = shutdownWriter(consoleLogging) proc shutdownThreadedFileLogging() = shutdownWriter(fileLogging) proc ensureFreshness*(ls: ThreadLocalLogService) = ## Check our thread-local version of the logging service configuration ## against the global log service definition. This uses an atomic version ## number to allow the check to be inexpensive, only incurring the more ## expensive copy operations if there are actual changes. if ls.isNil or ls.shared.isNil: raise newException(ValueError, "LogService not properly initialized. Use initLogService to obtain a" & "properly initialized LogService object") # ORC's cycle collector maintains some thread-local bookkeeping state. # Because of this, we have to be careful here while making a copy of the # shared logging configuration state to avoid behavior that would result in # temporary variables with ownership semantics (specifically the shared # appender references in the seq). # # We will keep a stable borrowed pointer while inspecting configuration and # will create temporary variables to own the data being copied that can be # cleaned up in this proc's scope. let state = ls.serviceHandle.shared if ls.configVersion == state.configVersion.load(): return block: # This block is a performance optimization. By putting these variables and # operations in their own scope they won't get initialized or cleaned up # unless ls.configVersion != state.configVersion.load(). # We want the following vars to be in the outer scope (not in the lock) so # that their cleanup happens after the lock is released. var newAppenders: seq[LogAppender] var newThresholds: TableRef[string, Level] withLock state.lock: let version = state.configVersion.load() for a in state.appenders: newAppenders.add(clone(a)) newThresholds = newTable[string, Level]() for ns, t in pairs(state.thresholds): newThresholds[ns] = t # Record the version update only after every copy succeeds; a failure # leaves the old version in place so the next freshness check retries the # refresh. swap(ls.appenders, newAppenders) swap(ls.thresholds, newThresholds) ls.configVersion = version proc initSharedLogServiceState( rootLevel = lvlAll, errorHandler = defaultErrorHandlerFunc): ptr SharedLogServiceState = result = cast[ptr SharedLogServiceState]( allocShared0(sizeof(SharedLogServiceState))) result.owners.store(1) result.configVersion.store(0) initLock(result.lock) initLock(result.errorHandlerLock) result.appenders = @[] result.thresholds = initTable[string, Level]() result.rootLevel.store(rootLevel) result.errorHandler = errorHandler proc initLogService*( rootLevel = lvlAll, errorHandler = defaultErrorHandlerFunc): LogService = ## Initialize an independently owned shared configuration handle. Copies ## retain the shared control block atomically, including copies in worker ## arguments and local services. The original handle need not outlive them. ## The resulting *LogService* object can be safely passed between threads to ## initialize *ThreadLocalLogService* objects but note that thread-safe use ## still requires that appenders and formatters satisfy the ownership ## requirements documented on *LogAppender.* ## ## Multiple calls to *initLogService* will result in completely independent ## *LogService* objects with their own synchronized configuration and global ## state. result.shared = initSharedLogServiceState(rootLevel, errorHandler) proc threadLocalRef*(ls: LogService): ThreadLocalLogService = ## Build a fresh cache in the calling thread, retaining only the shared ## handle. Never copy another thread's cached appender or threshold refs. result = ThreadLocalLogService(serviceHandle: ls, configVersion: UninitializedConfigVersion) ensureFreshness(result) proc reportLoggingError( state: ptr SharedLogServiceState, err: ref Exception, msg: string) = var handler: ErrorHandlerFunc withLock state.errorHandlerLock: handler = state.errorHandler if not handler.isNil: try: handler(err, msg) except: # If the error handler itself fails, try the default as a last resort try: defaultErrorHandlerFunc(err, msg) except Exception: discard # we tried... func fmtLevel(lvl: Level): string {.gcsafe.} = case lvl of lvlDebug: return "DEBUG" of lvlInfo: return "INFO" of lvlNotice: return "NOTICE" of lvlWarn: return "WARN" of lvlError: return "ERROR" of lvlFatal: return "FATAL" else: return "UNKNOWN" func `%`*(msg: LogMessage): JsonNode = result = %*{ "scope": msg.scope, "level": fmtLevel(msg.level), "msg": msg.msg, "ts": msg.ts.formatIso8601 } if msg.err.isSome: result["err"] = %($msg.err.get.name & ": " & msg.err.get.msg) result["stacktrace"] = %($msg.err.get.trace) if msg.additionalData.kind == JObject: for (k, v) in pairs(msg.additionalData): if not result.hasKey(k): result[k] = v # Don't allow overwriting builtin field names proc setErrorHandler*( ls: var LogService, errHandler = defaultErrorHandlerFunc) {.gcsafe} = if errHandler.isNil: return withLock ls.shared.errorHandlerLock: ls.shared.errorHandler = errHandler proc setErrorHandler*( ls: ThreadLocalLogService, errHandler = defaultErrorHandlerFunc) {.gcsafe.} = setErrorHandler(ls.serviceHandle, errHandler) proc setRootThreshold*(ls: var LogService, lvl: Level) {.gcsafe.} = ls.shared.rootLevel.store(lvl) ls.shared.configVersion.atomicInc proc setRootThreshold*(ls: ThreadLocalLogService, lvl: Level) {.gcsafe.} = setRootThreshold(ls.serviceHandle, lvl) func formatSimpleTextLog*(msg: LogMessage): string {.gcsafe.} = msg.msg func formatJsonStructuredLog*(msg: LogMessage): string {.gcsafe.} = $(%msg) proc setThreshold*(ls: var LogService, scope: string, lvl: Level) {.gcsafe.} = withLock ls.shared.lock: ls.shared.thresholds[scope] = lvl ls.shared.configVersion.atomicInc proc setThreshold*(ls: ThreadLocalLogService, scope: string, lvl: Level) {.gcsafe.} = setThreshold(ls.serviceHandle, scope, lvl) ensureFreshness(ls) proc setThresholds*(ls: var LogService, thresholds: TableRef[string, Level]) {.gcsafe.} = withLock ls.shared.lock: for k,v in thresholds: ls.shared.thresholds[k] = v ls.shared.configVersion.atomicInc proc setThresholds*(ls: ThreadLocalLogService, thresholds: TableRef[string, Level]) {.gcsafe.} = setThresholds(ls.serviceHandle, thresholds) ensureFreshness(ls) proc getLogger*( ls: ThreadLocalLogService, scope: string, lvl: Option[Level] = none[Level]()): Logger {.gcsafe.} = ## Retrieve a thread-local *Logger* instance. The *lvl* parameter exists as a ## convenience to allow you to set the logging level for a logging namespace ## and create a logger for it. Passing a value in *lvl*, like: ## ## let logger = ls.getLogger('app/api', some(lvlInfo)) ## ## is equivalent to: ## ## ls.setThreshold('app/api', lvlInfo) ## let logger = ls.getLogger('app/api') ## ## **Note:** Logger instances must stay within the context of a single thread. ## They are not safe to share across thread boundaries. # setThreshold will ensure freshness if lvl.isSome: ls.setThreshold(scope, lvl.get) else: ensureFreshness(ls) result = Logger(scope: scope, threadSvc: ls) proc getLogger*( ls: Option[ThreadLocalLogService], scope: string, lvl: Option[Level] = none[Level]()): Option[Logger] {.gcsafe.} = return if ls.isSome: some(getLogger(ls.get, scope, lvl)) else: none[Logger]() proc appenders*(ls: var LogService): seq[LogAppender] {.gcsafe.} = withLock ls.shared.lock: for a in ls.shared.appenders: result.add(clone(a)) proc appenders*(ls: ThreadLocalLogService): seq[LogAppender] {.gcsafe.} = for a in ls.appenders: result.add(clone(a)) proc addAppender*(ls: var LogService, appender: LogAppender) {.gcsafe.} = ## Add a log appender to the shared configuration. Local services refresh ## their cached state on their next freshness check. withLock ls.shared.lock: var copiedAppender = clone(appender) ls.shared.appenders.add(copiedAppender) ls.shared.configVersion.atomicInc proc addAppender*(ls: ThreadLocalLogService, appender: LogAppender) {.gcsafe.} = addAppender(ls.serviceHandle, appender) ensureFreshness(ls) proc clearAppenders*(ls: var LogService) {.gcsafe.} = ## Remove all shared appenders. Local services refresh their cached state ## on their next freshness check. withLock ls.shared.lock: ls.shared.appenders = @[] ls.shared.configVersion.atomicInc proc clearAppenders*(ls: ThreadLocalLogService) {.gcsafe.} = clearAppenders(ls.serviceHandle) func getEffectiveThreshold(logger: Logger): Level {.gcsafe.} = ## Get the effective logging level threshold for a logger. This is the most ## specific level that is set for the logger or any of its parents. The root ## logger is used as the default if no other level is set. result = logger.threadSvc.shared.rootLevel.load # Check for exact match first if logger.threadSvc.thresholds.hasKey(logger.scope): return logger.threadSvc.thresholds[logger.scope] # Find all matching namespaces, sorted with the most specific first let namespaces = toSeq(keys(logger.threadSvc.thresholds)) .filterIt(logger.scope.startsWith(it)) .sorted(SortOrder.Descending) # If we have matches, return the threshold configured for the most specific. if namespaces.len > 0: result = logger.threadSvc.thresholds[namespaces[0]] proc isEnabled*(l: Logger, lvl: Level): bool {.inline,gcsafe.} = lvl >= l.getEffectiveThreshold proc sendToAppenders(logger: Logger, msg: LogMessage) {.gcsafe,inline.} = for app in logger.threadSvc.appenders: if logger.scope.startsWith(app.namespace) and msg.level >= app.threshold: app.appendLogMessage(logger.threadSvc, msg) template log*(l: Logger, lm: LogMessage) = ensureFreshness(l.threadSvc) if lm.level >= l.getEffectiveThreshold: sendToAppenders(l, lm) template log*(l: Logger, lvl: Level, msg: untyped) = ensureFreshness(l.threadSvc) if lvl >= l.getEffectiveThreshold: sendToAppenders(l, initLogMessage(l.scope, lvl, msg)) template log*(l: Logger, lvl: Level, err: ref Exception, msg: untyped) = ensureFreshness(l.threadSvc) if lvl >= l.getEffectiveThreshold: sendToAppenders(l, initLogMessage( l.scope, lvl, msg, some(cast[ref Exception](err)))) template log*(l: Option[Logger], lm: LogMessage) = if l.isSome: log(l.get, lm) template log*(l: Option[Logger], lvl: Level, msg: untyped) = if l.isSome: log(l.get, lvl, msg) template log*( l: Option[Logger], lvl: Level, err: ref Exception, msg: untyped) = if l.isSome: log(l.get, lvl, err, msg) template debug*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlDebug, msg) template info*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlInfo, msg) template notice*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlNotice, msg) template warn*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlWarn, msg) template warn*[L: Logger or Option[Logger], M](l: L, err: ref Exception, msg: M) = log(l, lvlWarn, err, msg) template error*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlError, msg) template error*[L: Logger or Option[Logger], M](l: L, err: ref Exception, msg: M) = log(l, lvlError, err, msg) template fatal*[L: Logger or Option[Logger], M](l: L, msg: M) = log(l, lvlFatal, msg) template fatal*[L: Logger or Option[Logger], M](l: L, err: ref Exception, msg: M) = log(l, lvlFatal, err, msg) # ----------------------------------------------------------------------------- # Writer Thread Implementations # ----------------------------------------------------------------------------- proc consoleWriterLoop() {.thread.} = while true: let message = consoleLogging.chan.recv() if message.stop: break try: let output = if message.useStderr: stderr else: stdout output.write(message.msg) output.flushFile() except IOError: discard proc fileWriterLoop() {.thread.} = const bufLen = 128 var msgsByPath = newTable[Path, seq[FileMessage]]() while true: var msgBuf: array[bufLen, FileMessage] msgBuf[0] = fileLogging.chan.recv() var recvIdx = 1 var writeIdx = 0 var stopping = msgBuf[0].stop while not stopping and recvIdx < bufLen: let (available, message) = fileLogging.chan.tryRecv() if not available: break msgBuf[recvIdx] = message inc recvIdx stopping = message.stop # Organize messages by destination file msgsByPath.clear() while writeIdx < recvIdx: let fMsgObj = msgBuf[writeIdx] inc writeIdx if not fMsgObj.stop: if not msgsByPath.contains(fMsgObj.absPath): msgsByPath[fMsgObj.absPath] = @[] msgsByPath[fMsgObj.absPath].add(fMsgObj) # Write all messages in file order to optimize file open/flush/close for path, msgs in pairs(msgsByPath): var f: File if not open(f, $path, fmAppend): # TODO: can we do better than silently failing here? continue for m in msgs: try: writeLine(f, m.msg) except Exception: discard flushFile(f) close(f) # The final batch must be written before honoring its stop message. if stopping: break proc sendConsoleMessage(message: ConsoleMessage) = withLock consoleLogging.lock: if consoleLogging.shutdown: raise newException(IOError, "Console logging has shut down") if not consoleLogging.initialized: consoleLogging.chan.open() createThread(consoleLogging.writerThread, consoleWriterLoop) consoleLogging.initialized = true consoleLogging.chan.send(message) proc sendFileMessage(message: FileMessage) = withLock fileLogging.lock: if fileLogging.shutdown: raise newException(IOError, "File logging has shut down") if not fileLogging.initialized: fileLogging.chan.open() createThread(fileLogging.writerThread, fileWriterLoop) fileLogging.initialized = true fileLogging.chan.send(message) # ----------------------------------------------------------------------------- # LogFormatter Implementation # ----------------------------------------------------------------------------- method clone*(formatter: LogFormatter): LogFormatter {.base, gcsafe.} = raise newException(CatchableError, "missing formatter clone implementation") method format*(formatter: LogFormatter, msg: LogMessage): string {.base, gcsafe.} = raise newException(CatchableError, "missing formatter implementation") method clone(formatter: StatelessLogFormatterImpl): LogFormatter {.gcsafe.} = StatelessLogFormatterImpl(callback: formatter.callback) method format(formatter: StatelessLogFormatterImpl, msg: LogMessage): string {.gcsafe.} = formatter.callback(msg) proc initLogFormatter*(callback: StatelessLogFormatterFunc): LogFormatter = if callback.isNil: raise newException(ValueError, "Log formatter callback is nil") StatelessLogFormatterImpl(callback: callback) converter toLogFormatter*(callback: StatelessLogFormatterFunc): LogFormatter = ## Noncapturing formatter functions remain convenient constructor arguments. initLogFormatter(callback) method clone[S](formatter: FactoryLogFormatterImpl[S]): LogFormatter {.gcsafe.} = FactoryLogFormatterImpl[S](seed: formatter.seed, factory: formatter.factory) method format[S](formatter: FactoryLogFormatterImpl[S], msg: LogMessage): string {.gcsafe.} = if formatter.local.isNil: formatter.local = formatter.factory(formatter.seed) if formatter.local.isNil: raise newException(ValueError, "Log formatter factory returned nil") formatter.local(msg) proc initLogFormatter*[S](seed: S, factory: proc(seed: S): StatefulLogFormatterFunc {.gcsafe, nimcall.}): LogFormatter = ## The seed is copied by value. The noncapturing factory creates a closure ## separately for each clone on first use; live closure state is never copied. requireThreadValue(S) if factory.isNil: raise newException(ValueError, "Log formatter factory is nil") FactoryLogFormatterImpl[S](seed: seed, factory: factory) # ----------------------------------------------------------------------------- # CustomLogAppender Implementation # ----------------------------------------------------------------------------- proc initCustomLogAppender*[T]( state: T, doLogMessage: CustomLogAppenderFunc[T], namespace = "", threshold = lvlAll): CustomLogAppender[T] {.gcsafe.} = ## Copy value state into each appender clone. For shared mutable state, pass ## a SharedLogState handle. For local refs or closures, use a factory. requireThreadValue(T) if doLogMessage.isNil: raise newException(ValueError, "initCustomLogAppender: doLogMessage is nil") result = CustomLogAppender[T]( namespace: namespace, threshold: threshold, doLogMessage: doLogMessage, state: state) method clone*[T](cla: CustomLogAppender[T]): LogAppender {.gcsafe.} = requireThreadValue(T) assert not cla.doLogMessage.isNil, "CustomLogAppender#clone: source doLogMessage is nil" result = CustomLogAppender[T]( namespace: cla.namespace, threshold: cla.threshold, doLogMessage: cla.doLogMessage, state: cla.state) method appendLogMessage[T]( cla: CustomLogAppender[T], ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: if cla.doLogMessage.isNil: raise newException(ValueError, "CustomLogAppender.appendLogMessage: doLogMessage is nil") else: cla.doLogMessage(cla.state, msg) except Exception: ls.shared.reportLoggingError( getCurrentException(), "unable to append to CustomLogAppender") proc initFactoryCustomLogAppender*[S, T](seed: S, factory: proc(seed: S): T {.gcsafe, nimcall.}, doLogMessage: CustomLogAppenderFunc[T], namespace = "", threshold = lvlAll): FactoryCustomLogAppender[S, T] = ## Only the seed crosses threads. State returned by the factory may contain ## refs and closures, and must be independently owned by the calling thread. requireThreadValue(S) if factory.isNil or doLogMessage.isNil: raise newException(ValueError, "Factory custom appender callbacks must not be nil") FactoryCustomLogAppender[S, T](seed: seed, factory: factory, doLogMessage: doLogMessage, namespace: namespace, threshold: threshold) method clone[S, T](app: FactoryCustomLogAppender[S, T]): LogAppender {.gcsafe.} = FactoryCustomLogAppender[S, T](seed: app.seed, factory: app.factory, doLogMessage: app.doLogMessage, namespace: app.namespace, threshold: app.threshold) method appendLogMessage[S, T](app: FactoryCustomLogAppender[S, T], ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: if not app.initialized: app.local = app.factory(app.seed) app.initialized = true app.doLogMessage(app.local, msg) except Exception: ls.shared.reportLoggingError(getCurrentException(), "unable to append to FactoryCustomLogAppender") # ----------------------------------------------------------------------------- # ConsoleLogAppender Implementation # ----------------------------------------------------------------------------- proc initConsoleLogAppender*( formatter: LogFormatter = nil, useStderr = false, namespace = "", threshold = lvlAll): ConsoleLogAppender {.gcsafe.} = ## Initialize a new ConsoleLogAppender. formatter defaults to ## formatSimpleTextLog. formatJsonStructuredLog is another useful formatter ## provided (or you can write your own) result = ConsoleLogAppender( namespace: namespace, threshold: threshold, formatter: (if formatter.isNil: initLogFormatter(formatSimpleTextLog) else: clone(formatter)), useStderr: useStderr) method clone*(cla: ConsoleLogAppender): LogAppender {.gcsafe.} = result = ConsoleLogAppender( namespace: cla.namespace, threshold: cla.threshold, formatter: clone(cla.formatter), useStderr: cla.useStderr) proc appendLogMessageMultiThreaded( cla: ConsoleLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: sendConsoleMessage(ConsoleMessage( msg: cla.formatter.format(msg), useStderr: cla.useStderr)) except Exception: try: let output = if cla.useStderr: stderr else: stdout output.writeLine(cla.formatter.format(msg)) output.writeLine(cla.formatter.format(LogMessage( scope: "namespaced_logging", level: lvlError, err: some(getCurrentException()), ts: now(), msg: "Unable to write log to channel in multi-threaded context." ))) output.flushFile() except Exception: discard proc appendLogMessageSingleThreaded( cla: ConsoleLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: let output = if cla.useStderr: stderr else: stdout output.writeLine(cla.formatter.format(msg)) output.flushFile() except Exception: discard method appendLogMessage( cla: ConsoleLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = if msg.level < cla.threshold: return try: when defined(multithreaded): cla.appendLogMessageMultiThreaded(ls, msg) else: cla.appendLogMessageSingleThreaded(ls, msg) except Exception: ls.shared.reportLoggingError( getCurrentException(), "unable to append to ConsoleLogAppender") # ----------------------------------------------------------------------------- # FileLogAppender Implementation # ----------------------------------------------------------------------------- proc initFileLogAppender*( filePath: string, formatter: LogFormatter = nil, namespace = "", threshold = lvlAll): FileLogAppender {.gcsafe.} = ## Initialize a new FileLogAppender. formatter defaults to ## formatSimpleTextLog. formatJsonStructuredLog is another useful formatter ## provided (or you can write your own) result = FileLogAppender( namespace: namespace, threshold: threshold, formatter: (if formatter.isNil: initLogFormatter(formatSimpleTextLog) else: clone(formatter)), absPath: absolutePath(Path(filePath))) method clone*(fla: FileLogAppender): LogAppender {.gcsafe.} = result = FileLogAppender( namespace: fla.namespace, threshold: fla.threshold, formatter: clone(fla.formatter), absPath: fla.absPath) proc appendLogMessageMultiThreaded( fla: FileLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: sendFileMessage(FileMessage( msg: fla.formatter.format(msg), absPath: fla.absPath)) except Exception: discard proc appendLogMessageSingleThreaded( fla: FileLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = try: var f: File if not open(f, $fla.absPath, fmAppend): return writeLine(f, fla.formatter.format(msg)) flushFile(f) close(f) except Exception: discard method appendLogMessage( fla: FileLogAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = if msg.level < fla.threshold: return try: when defined(multithreaded): fla.appendLogMessageMultiThreaded(ls, msg) else: fla.appendLogMessageSingleThreaded(ls, msg) except Exception: ls.shared.reportLoggingError( getCurrentException(), "unable to append to FileLogAppender") # ----------------------------------------------------------------------------- # StdLoggingAppender Implementation # ----------------------------------------------------------------------------- func formatForwardedLog*(lm: LogMessage): string = ## Default formatter for the StdLoggingAppender that prepends the logger ## scope to the message before formatting the message via ## *formatSimpleTextLog* "[" & lm.scope & "] " & formatSimpleTextLog(lm) proc initStdLoggingAppender*( fallbackOnly = true, formatter: LogFormatter = nil, namespace = "", threshold = lvlAll): StdLoggingAppender {.gcsafe.} = result = StdLoggingAppender( namespace: namespace, threshold: threshold, fallbackOnly: fallbackOnly, formatter: (if formatter.isNil: initLogFormatter(formatForwardedLog) else: clone(formatter))) method clone*(sla: StdLoggingAppender): LogAppender {.gcsafe.} = result = StdLoggingAppender( namespace: sla.namespace, threshold: sla.threshold, fallbackOnly: sla.fallbackOnly, formatter: clone(sla.formatter)) method appendLogMessage*( sla: StdLoggingAppender, ls: ThreadLocalLogService, msg: LogMessage) {.gcsafe.} = if sla.fallbackOnly and ls.appenders.len > 1: return stdlog.log(msg.level, sla.formatter.format(msg)) # ----------------------------------------------------------------------------- # Cleanup # ----------------------------------------------------------------------------- addExitProc(proc() = shutdownThreadedConsoleLogging() shutdownThreadedFileLogging() ) # ----------------------------------------------------------------------------- # Tests # ----------------------------------------------------------------------------- when isMainModule: import std/[files, os, tempfiles, unittest] import ./namespaced_logging/testutil suite "LogService Initialization": test "initLogService creates valid service": let ls = initLogService() let local = ls.threadLocalRef() check: ls.shared != nil ls.shared.owners.load() == 2 ls.shared.configVersion.load() == 0 ls.shared.rootLevel.load() == lvlAll local.configVersion >= 0 local.configVersion == ls.shared.configVersion.load test "initLogService with custom root level": let ls = initLogService(lvlInfo) check ls.shared.rootLevel.load() == lvlInfo test "threadLocalRef builds independent caches for an unchanged service": var service = initLogService() service.addAppender(initConsoleLogAppender()) service.setThreshold("worker", lvlInfo) let first = service.threadLocalRef() let second = service.threadLocalRef() check: first.shared == second.shared first.configVersion == second.configVersion cast[pointer](first.thresholds) != cast[pointer](second.thresholds) first.thresholds["worker"] == second.thresholds["worker"] first.appenders.len == 1 second.appenders.len == 1 first.appenders[0] != second.appenders[0] suite "LogService Configuration": setup: let ls = threadLocalRef(initLogService()) test "setRootThreshold updates level": ls.setRootThreshold(lvlError) check ls.shared.rootLevel.load() == lvlError test "setThreshold adds namespace threshold": ls.setThreshold("api", lvlWarn) check ls.thresholds["api"] == lvlWarn test "ensureFreshness syncs configuration": # Modify global state directly withLock ls.shared.lock: ls.shared.thresholds["test"] = lvlError ls.shared.configVersion.atomicInc() # Local state should be out of sync check not ls.thresholds.hasKey("test") # Ensure freshness should sync ls.ensureFreshness() check ls.thresholds.hasKey("test") check ls.thresholds["test"] == lvlError test "ensureFreshness syncs configuration between multiple loggers": let ls2 = ls.service.threadLocalRef() ls.setThreshold("api", lvlWarn) check: ls.configVersion == ls.shared.configVersion.load ls.configVersion != ls2.configVersion ls2.configVersion != ls.shared.configVersion.load ls.thresholds["api"] == lvlWarn ls.shared.thresholds["api"] == lvlWarn not ls2.thresholds.contains("api") ls2.ensureFreshness() check: ls.configVersion == ls2.configVersion ls2.configVersion == ls.shared.configVersion.load ls2.thresholds["api"] == lvlWarn test "ensureFreshness syncs configuration across threads": var tA, tB: Thread[LogService] var lock: Lock var cInitA, cInitB, cInitAll, cUpd: Cond initLock(lock) initCond(cInitAll) initCond(cInitA) initCond(cInitB) initCond(cUpd) proc runA(lsGiven: LogService) {.thread, gcsafe.} = let ls = lsGiven.threadLocalRef() withLock lock: # 1a. Initialize both threads cInitA.signal() wait(cInitAll, lock) # 2a. A updates global config ls.setThreshold("api", lvlWarn) cUpd.signal() proc runB(lsGiven: LogService) {.thread, gcsafe.} = let ls = lsGiven.threadLocalRef() withLock lock: # 1b. Initialize both threads cInitB.signal() # 3. B does not see the global config changes wait(cUpd, lock) check not ls.thresholds.contains("api") # B updates freshness and sees the change ls.ensureFreshness() check ls.thresholds["api"] == lvlWarn # 1. Initialize both threads createThread(tA, runA, ls.service) withLock lock: wait(cInitA, lock) createThread(tB, runB, ls.service) withLock lock: wait(cInitB, lock) cInitAll.broadcast() # finished with initialization joinThreads(tA, tB) test "configuration version incrementing": let initialVersion = ls.shared.configVersion.load() ls.setRootThreshold(lvlWarn) check ls.shared.configVersion.load() > initialVersion ls.setThreshold("test", lvlError) check ls.shared.configVersion.load() > initialVersion + 1 suite "Logger Creation and Usage": setup: let ls = threadLocalRef(initLogService()) let loggedMsgs = initLoggedMessages() ls.addAppender(initTestLogAppender(loggedMsgs)) test "getLogger creates logger with correct scope": let logger = ls.getLogger("api/users") check logger.scope == "api/users" test "getLogger with threshold sets namespace level": let logger = ls.getLogger("api/users", some(lvlWarn)) check ls.thresholds["api/users"] == lvlWarn test "log methods work": let logger = ls.getLogger("test") logger.log(lvlDebug, "debug string msg") logger.log(lvlInfo, %*{"msg": "info json msg"}) logger.log(lvlNotice, "notice string msg") logger.log(lvlError, newException(ValueError, "exception msg"), "error ex. msg") let lm = loggedMsgs.get() check: lm.len == 4 lm[0].level == lvlDebug lm[0].msg.contains("debug string msg") lm[1].level == lvlInfo lm[1].msg.contains("info json msg") lm[2].level == lvlNotice lm[2].msg.contains("notice string msg") lm[3].level == lvlError lm[3].msg.contains("error ex. msg") test "logger convenience methods work": let logger = ls.getLogger("test") logger.debug("debug message") logger.info("info message") logger.notice("notice message") logger.warn("warn message") logger.error("error message") logger.fatal("fatal message") let lm = loggedMsgs.get() check: lm.len == 6 lm[0].level == lvlDebug lm[1].level == lvlInfo lm[2].level == lvlNotice lm[3].level == lvlWarn lm[4].level == lvlError lm[5].level == lvlFatal test "logger with exception logging": let logger = ls.getLogger("test") let testException = newException(ValueError, "test error") logger.error(testException, "Something went wrong") let lm = loggedMsgs.get() check: lm.len == 1 lm[0].err.isSome lm[0].err.get.msg == "test error" test "optional logger methods": let logger = some(ls.getLogger("test")) let noLogger = none(Logger) logger.info("test message") noLogger.info("should not appear") let lm = loggedMsgs.get() check lm.len == 1 check lm[0].msg == "test message" suite "Threshold and Filtering": setup: let ls = threadLocalRef(initLogService()) let loggedMsgs = initLoggedMessages() ls.addAppender(initTestLogAppender(loggedMsgs)) test "root level filtering": ls.setRootThreshold(lvlInfo) let logger = ls.getLogger("test") logger.debug("should be filtered") logger.info("should appear") logger.error("should appear") let lm = loggedMsgs.get() check: lm.len == 2 lm[0].level == lvlInfo lm[1].level == lvlError test "namespace-specific threshold": ls.setThreshold("api", lvlWarn) let apiLogger = ls.getLogger("api/users") let dbLogger = ls.getLogger("db/users") apiLogger.info("api info - should be filtered") apiLogger.warn("api warn - should appear") dbLogger.info("db info - should appear") let lm = loggedMsgs.get() check: lm.len == 2 lm[0].scope == "api/users" lm[0].level == lvlWarn lm[1].scope == "db/users" lm[1].level == lvlInfo test "most specific threshold wins": ls.setThreshold("api", lvlWarn) ls.setThreshold("api/users", lvlDebug) let userLogger = ls.getLogger("api/users/detail") let orderLogger = ls.getLogger("api/orders") userLogger.debug("user debug - should appear") orderLogger.debug("order debug - should be filtered") let lm = loggedMsgs.get() check: lm.len == 1 lm[0].scope == "api/users/detail" lm[0].level == lvlDebug test "message construction is avoided if the message is not logged": var expensiveCallCount = 0 proc expensiveCall(): int = inc expensiveCallCount return expensiveCallCount ls.setThreshold("test", lvlInfo) let logger = ls.getLogger("test") logger.debug("Expensive call (" & $expensiveCall() & ")") logger.info("Expensive call (" & $expensiveCall() & ")") let lm = loggedMsgs.get() check: lm.len == 1 lm[0].msg.contains("Expensive call (1)") expensiveCallCount == 1 suite "Appender Functionality": setup: let ls = threadLocalRef(initLogService()) test "appender namespace filtering": let apiMsgs = initLoggedMessages() let dbMsgs = initLoggedMessages() let apiAppender = initTestLogAppender(apiMsgs, "api") let dbAppender = initTestLogAppender(dbMsgs, "db") ls.addAppender(apiAppender) ls.addAppender(dbAppender) let apiLogger = ls.getLogger("api/users") let dbLogger = ls.getLogger("db/connection") let otherLogger = ls.getLogger("other/service") apiLogger.info("api message") dbLogger.info("db message") otherLogger.info("other message") check: apiMsgs.get().len == 1 apiMsgs.get()[0].scope == "api/users" dbMsgs.get().len == 1 dbMsgs.get()[0].scope == "db/connection" test "appender threshold filtering": let loggedMsgs = initLoggedMessages() let warnAppender = initTestLogAppender(loggedMsgs, "", lvlWarn) ls.addAppender(warnAppender) let logger = ls.getLogger("test") logger.info("info message") logger.warn("warn message") logger.error("error message") let lm = loggedMsgs.get() check: lm.len == 2 lm[0].level == lvlWarn lm[1].level == lvlError suite "Console Appender Construction": setup: let ls = threadLocalRef(initLogService()) test "console appender initialization": let consoleAppender = initConsoleLogAppender() check consoleAppender.useStderr == false check consoleAppender.namespace == "" check consoleAppender.threshold == lvlAll test "console appender with custom settings": let consoleAppender = initConsoleLogAppender( useStderr = true, namespace = "error", threshold = lvlError ) check consoleAppender.useStderr == true check consoleAppender.namespace == "error" check consoleAppender.threshold == lvlError test "console appender clone": let original = initConsoleLogAppender(useStderr = true, namespace = "test") let cloned = clone(original) check cloned of ConsoleLogAppender let clonedConsole = ConsoleLogAppender(cloned) check clonedConsole.useStderr == true check clonedConsole.namespace == "test" suite "File Appender": setup: let ls = threadLocalRef(initLogService()) test "file appender initialization": let fileAppender = initFileLogAppender("tempfile.log") check fileAppender.absPath == absolutePath(Path("tempfile.log")) check fileAppender.namespace == "" check fileAppender.threshold == lvlAll test "file appender basic logging": let (_, pathStr) = createTempFile("nl_test_", ".tmp.log") let fileAppender = initFileLogAppender(pathStr) ls.addAppender(fileAppender) let logger = ls.getLogger("test") logger.info("test message") # Wait for file to be written let lines = waitForFileContent(pathStr, 1) check: lines.len == 1 "test message" in lines[0] removeFile(pathStr) test "file appender clone": let original = initFileLogAppender("tempfile.log", namespace = "test") let cloned = clone(original) check cloned of FileLogAppender let clonedFile = FileLogAppender(cloned) check clonedFile.absPath == original.absPath check clonedFile.namespace == "test" suite "StdLoggingAppender": var fileLogger: FileLogger var tempFile: File var tempFilename: string setup: let ls = threadLocalRef(initLogService()) (tempFile, tempFilename) = createTempFile("stdlog_test", ".tmp.log") fileLogger = newFileLogger(tempFile, flushThreshold = lvlAll) addHandler(fileLogger) teardown: removeHandler(fileLogger) try: close(tempFile) except Exception: discard removeFile(tempFilename) test "forwards to std logging": ls.addAppender(initStdLoggingAppender()) let logger = ls.getLogger("test") logger.debug("message at debug") logger.info("message at info") logger.error("message at error") tempFile.flushFile() close(tempFile) check open(tempFile, tempFilename, fmRead) let lines = toSeq(lines(tempFile)) check: lines.len == 3 lines[0] == "DEBUG [test] message at debug" lines[1] == "INFO [test] message at info" lines[2] == "ERROR [test] message at error" test "fallbackOnly works when on": ls.addAppender(initStdLoggingAppender()) let logger = ls.getLogger("test") logger.debug("message at debug") logger.info("message at info") logger.error("message at error") let loggedMsgs = initLoggedMessages() ls.addAppender(initTestLogAppender(loggedMsgs)) logger.notice("message at notice") logger.warn("message at warn") logger.fatal("message at fatal") tempFile.flushFile() close(tempFile) check open(tempFile, tempFilename, fmRead) let lines = toSeq(lines(tempFile)) let lm = loggedMsgs.get() check: lines.len == 3 lines[0] == "DEBUG [test] message at debug" lines[1] == "INFO [test] message at info" lines[2] == "ERROR [test] message at error" lm.len == 3 lm[0].msg.contains("message at notice") lm[1].msg.contains("message at warn") lm[2].msg.contains("message at fatal") test "fallbackOnly works when off": ls.addAppender(initStdLoggingAppender(fallbackOnly = false)) let logger = ls.getLogger("test") logger.debug("message at debug") logger.info("message at info") logger.error("message at error") let loggedMsgs = initLoggedMessages() ls.addAppender(initTestLogAppender(loggedMsgs)) logger.notice("message at notice") logger.warn("message at warn") logger.fatal("message at fatal") tempFile.flushFile() close(tempFile) check open(tempFile, tempFilename, fmRead) let lines = toSeq(lines(tempFile)) let lm = loggedMsgs.get() check: lines.len == 6 lines[0] == "DEBUG [test] message at debug" lines[1] == "INFO [test] message at info" lines[2] == "ERROR [test] message at error" lines[3] == "NOTICE [test] message at notice" lines[4] == "WARN [test] message at warn" lines[5] == "FATAL [test] message at fatal" lm.len == 3 lm[0].msg.contains("message at notice") lm[1].msg.contains("message at warn") lm[2].msg.contains("message at fatal") type WriterShutdownProbe = object path: Path ready: Atomic[int] start: Atomic[bool] accepted: array[4, int] proc submitDuringShutdown(args: tuple[probe: ptr WriterShutdownProbe, worker: int]) {.thread.} = let probe = args.probe let worker = args.worker sendFileMessage(FileMessage(absPath: probe.path, msg: $worker & ":0")) probe.accepted[worker] = 1 probe.ready.atomicInc() while not probe.start.load(): discard for i in 1 ..< 10_000: try: sendFileMessage(FileMessage(absPath: probe.path, msg: $worker & ":" & $i)) inc probe.accepted[worker] except IOError: break suite "Background writer lifecycle": test "shutdown drains accepted records while excluding further sends": let directory = createTempDir("namespaced_logging_lifecycle_", "") defer: removeDir(directory) var probe = WriterShutdownProbe(path: Path(directory / "messages.log")) var workers: array[4, Thread[tuple[probe: ptr WriterShutdownProbe, worker: int]]] for i in 0 ..< workers.len: createThread(workers[i], submitDuringShutdown, (addr probe, i)) while probe.ready.load() != workers.len: discard probe.start.store(true) shutdownThreadedFileLogging() joinThreads(workers) # Shutdown is permanent and repeatable; it must never reopen the channel. shutdownThreadedFileLogging() expect IOError: sendFileMessage(FileMessage(absPath: probe.path, msg: "too late")) var received: array[4, int] for line in readFile($probe.path).splitLines(): if line.len == 0: continue let parts = line.split(':') require parts.len == 2 let worker = parseInt(parts[0]) require worker in 0 ..< workers.len check parseInt(parts[1]) == received[worker] inc received[worker] check received == probe.accepted test "console shutdown wakes an empty writer and rejects further sends": sendConsoleMessage(ConsoleMessage(msg: "")) shutdownThreadedConsoleLogging() shutdownThreadedConsoleLogging() expect IOError: sendConsoleMessage(ConsoleMessage(msg: ""))