Add convenience methods for setting thresholds.

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, even when namespaced_logging is configured.

.gitignore

@@ -3,3 +3,4 @@ nimcache/
 tests/tests
 src/namespaced_logging.out
 src/namespaced_logging/autoconfigured
+.worktrees

README.md

@@ -8,7 +8,7 @@ four main motivating features:
 - Safe and straightforward to use in multi-threaded applications.
 - Native support for structured logging.
 - Simple, autoconfigured usage pattern reminiscent of the
-  [std/logging][std-logging] interface.
+  [std/logging][std-logging] interface (*not yet implemented*)
 
 ## Getting Started
 
@@ -21,38 +21,6 @@ nimble install https://github.com/jdbernard/nim-namespaced-logging
 
 ## Usage Patterns
 
-### Simple, Autoconfigured Setup
-```nim
-import namespaced_logging/autoconfigured
-
-# Zero configuration of the LogService required, appender/logger configuration
-# is immediately available
-addLogAppender(initConsoleLogAppender())
-info("Application started")
-
-# Set global threshold
-setRootLoggingThreshold(lvlWarn)
-
-# Namespaced loggers, thresholds, and appenders supported
-addLogAppender(initFileLogAppender(
-  filePath = "/var/log/app_db.log",
-  formatter = formatJsonStructuredLog, # provided in namespaced_logging
-  namespace = "app/db",
-  threshold = lvlInfo))
-
-# in DB code
-let dbLogger = getLogger("app/db/queryplanner")
-dbLogger.debug("Beginning query plan...")
-
-# native support for structured logs (import std/json)
-dbLogger.debug(%*{
-  "method": "parseParams",
-  "message": "unrecognized param type",
-  "invalidType": $params[idx].type,
-  "metadata": %(params.meta)
-} )
-```
-
 ### Manual Configuration
 ```nim
 import namespaced_logging
@@ -72,34 +40,6 @@ let apiLogger = localLogSvc.getLogger("api")
 let dbLogger = localLogSvc.getLogger("db")
 ```
 
-### Autoconfigured Multithreaded Application
-```nim
-import namespaced_logging/autoconfigured
-import mummy, mummy/routers
-
-# Main thread setup
-addLogAppender(initConsoleLogAppender())
-
-proc createApiRouter*(apiCtx: ProbatemApiContext): Router =
-  # This will run on a separate thread, but the thread creation is managed by
-  # mummy, not us. Log functions still operate correctly and respect the
-  # configuration setup on the main thread
-  let logger = getLogger("api")
-  logger.trace(%*{ "method_entered": "createApiRouter" })
-
-  # API route setup...
-
-  logger.debug(%*{ "method": "createApiRouter", "routes": numRoutes })
-
-
-let server = newServer(createApiRouter(), workerThreads = 4)
-ctx.server.serve(Port(8080))
-info("Serving MyApp v1.0.0 on port 8080")
-
-setThreshold("api", lvlTrace) # will be picked up by loggers on worker threads
-```
-
-
 ### Manual Multithreaded Application
 ```nim
 import namespaced_logging
@@ -225,6 +165,26 @@ by destination file, opens the file with mode `fmAppend`, writes the current
 batch of log messages, and then closes the file handle. Because of this, it has
 no problem if another process moves or truncates any of the target log files.
 
+### StdLoggingAppender
+
+Provides a fallback to [std/logging][std-logging]-based logging. This is
+primarily intended for use in libraries or other contexts where you want to
+fall back to std/logging if the application is not using or hasn't configured
+namespaced\_logging.
+
+By default the *StdLoggingAppender* only logs when no namespaced\_logging
+appenders are configured but it can also be configured to always forward log
+messages regardless of whether namespaced\_logging has other appenders by
+setting `fallbackOnly = false`.
+
+```nim
+func initStdLoggingAppender*(
+    fallbackOnly = true,
+    formatter = formatForwardedLog,
+    namespace = "",
+    threshold = lvlAll): StdLoggingAppender {.gcsafe.}
+```
+
 ### CustomLogAppender
 
 Provides an extension point for custom logging implementations.
@@ -244,7 +204,7 @@ for the custom functionality.
 *TODO: rethink this. I chose this to avoid GC-safety issues copying closures
 across threads, but maybe I don't need this separate, explicit state field.*
 
-> [!WARNING] The `state` data type must support copy semantics on assignment.
+> [!CAUTION] The `state` data type must support copy semantics on assignment.
 > It is possible to pass a `ref` to `state` and/or data structures that include
 > `ref`s, but **you must guarantee they remain valid**, either by allocating
 > shared memeory, or (preferably) keeping alive a reference to them that the GC
@@ -263,26 +223,17 @@ behave more intuitively in a multi-threaded environment than
 true in environments where the logging setup code may be separated from the
 thread-management code (in an HTTP server, for example).
 
-As described in the [Getting Started](#getting-started) section, you can use
-the `namespaced_logging/autoconfigured` import to use a simplified interface
-that more closely matches the contract of [std/logging][std-logging]. In this
-case all thread and state management is done for you. The only limitation is
-that you cannot create multiple global *LogService* instances. In practice this
-is an uncommon need.
+The *LogService* object is the main entry point for the logging system and
+should be initialized on the main thread. The *LogService* contains a reference
+to the "source of truth" for logging configuration and is safe to be shared
+between all threads.
 
-If you do need or want the flexibility to manage the state yourself, import
-`namespaced_logging` directly. In this case, the thread which initialized
-*LogService* must also be the longest-living thread that uses that *LogService*
-instance. If the initializing thread terminates or the *LogService* object in
-that thread goes out of scope while other threads are still running and using
-the *LogService*, the global state may be harvested by the garbage collector,
-leading to use-after-free errors when other threads attempt to log (likely
-causing segfaults).
-
-When managing the state yourself, the *LogService* object is the main entry
-point for the logging system and should be initialized on the main thread. The
-*LogService* contains a reference to the "source of truth" for logging
-configuration and is safe to be shared between all threads.
+The thread which initializes a *LogService* must also be the longest-living
+thread that uses that *LogService* instance. If the initializing thread
+terminates or the *LogService* object in that thread goes out of scope while
+other threads are still running and using the *LogService*, the global state
+may be harvested by the garbage collector, leading to use-after-free errors
+when other threads attempt to log (likely causing segfaults).
 
 Individual threads should use the *threadLocalRef* proc to obtain a
 *ThreadLocalLogService* reference that can be used to create *Logger* objects.
@@ -488,6 +439,7 @@ logService.setErrorHandler(silentErrorHandler)
 ### Best Practices
 
 #### Provide Fallbacks
+
 ```nim
 proc robustErrorHandler(err: ref Exception, msg: string) {.gcsafe, nimcall.} =
   # Primary: Send to monitoring system

namespaced_logging.nimble

@@ -1,6 +1,6 @@
 # Package
 
-version       = "1.1.0"
+version       = "2.0.3"
 author        = "Jonathan Bernard"
 description   = "Wrapper around std/logging to provide namespaced logging."
 license       = "MIT"
@@ -13,3 +13,7 @@ requires @["nim >= 2.2.0", "zero_functional"]
 
 # from https://git.jdb-software.com/jdb/nim-packages
 requires "timeutils"
+
+task test, "Run unittests for the package.":
+  exec "nimble c src/namespaced_logging.nim"
+  exec "src/namespaced_logging.out"

src/namespaced_logging.nim

@@ -1,9 +1,10 @@
-import std/[algorithm, atomics, json, locks, options, os, paths, sequtils,
-            strutils, tables, times]
+import std/[algorithm, atomics, exitprocs, json, locks, options, os, paths,
+            sequtils, strutils, tables, times]
 import timeutils
+import std/logging as stdlog
 
-from logging import Level
-export logging.Level
+from std/logging import Level
+export Level
 
 type
   GlobalLogServiceObj {.acyclic.} = object
@@ -15,13 +16,9 @@ type
     thresholds: TableRef[string, Level]
     rootLevel: Atomic[Level]
 
-    console: ThreadedConsoleLoggingState
-    file: ThreadedFileLoggingState
-
     errorHandler: ErrorHandlerFunc
     errorHandlerLock: Lock
 
-
   GlobalLogService = ref GlobalLogServiceObj
 
 
@@ -41,7 +38,7 @@ type
   ThreadLocalLogService* = ref LogService
 
 
-  Logger* = object
+  Logger* = ref object
     scope*: string
     threadSvc: ThreadLocalLogService
 
@@ -87,18 +84,11 @@ type
     absPath: Path
 
 
-  ThreadedConsoleLoggingState = object
+  LogWriterThreadState[M] = object
     initialized: Atomic[bool]
     shutdown: Atomic[bool]
-    chan: Channel[ConsoleMessage]
-    writerThread: Thread[GlobalLogService]
-
-
-  ThreadedFileLoggingState = object
-    initialized: Atomic[bool]
-    shutdown: Atomic[bool]
-    chan: Channel[FileMessage]
-    writerThread: Thread[GlobalLogService]
+    chan: Channel[M]
+    writerThread: Thread[void]
 
 
   ConsoleLogAppender* = ref object of LogAppender
@@ -123,6 +113,61 @@ type
     formatter*: LogMessageFormatter
     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*: LogMessageFormatter
+
+const UninitializedConfigVersion = low(int)
+let JNULL = newJNull()
+
+var consoleLogging {.global.}: LogWriterThreadState[ConsoleMessage]
+var fileLogging {.global.}: LogWriterThreadState[FileMessage]
+var loggingThreadInitLock {.global.}: Lock
+
+initLock(loggingThreadInitLock)
+
+
+proc initLogMessage*(
+    scope: string,
+    lvl: Level,
+    message: string,
+    error: Option[ref Exception] = none[ref Exception](),
+    additionalData: JsonNode = JNULL): LogMessage =
+
+  LogMessage(
+    scope: scope,
+    level: lvl,
+    error: error,
+    timestamp: now(),
+    message: message,
+    additionalData: additionalData)
+
+
+proc initLogMessage*(
+    scope: string,
+    lvl: Level,
+    msg: JsonNode,
+    error: Option[ref Exception] = none[ref Exception]()): LogMessage =
+
+  LogMessage(
+    scope: scope,
+    level: lvl,
+    error: error,
+    timestamp: now(),
+    message:
+      if msg.hasKey("message"): msg["message"].getStr
+      else: "",
+    additionalData: msg)
+
 
 method clone*(app: LogAppender): LogAppender {.base, gcsafe.} =
   raise newException(CatchableError, "missing concrete implementation")
@@ -144,40 +189,39 @@ proc defaultErrorHandlerFunc*(
     stderr.flushFile()
   except Exception: discard # we tried...
 
-proc shutdownThreadedConsoleLogging(gls: var GlobalLogServiceObj) =
-  if not gls.console.initialized.load(): return
+proc shutdownThreadedConsoleLogging() =
+  if not consoleLogging.initialized.load(): return
 
-  gls.console.shutdown.store(true) # signal shutdown
+  withLock loggingThreadInitLock:
+    consoleLogging.shutdown.store(true) # signal shutdown
 
-  # Send sentinel values to wake up the writer thread
-  try: gls.console.chan.send(ConsoleMessage(message: "", useStderr: false))
-  except Exception: discard
+    # Send sentinel values to wake up the writer thread
+    try: consoleLogging.chan.send(ConsoleMessage(message: "", useStderr: false))
+    except Exception: discard
 
-  joinThread(gls.console.writerThread)
-  gls.console.chan.close()
-  gls.console.initialized.store(false)
+    joinThread(consoleLogging.writerThread)
+    consoleLogging.chan.close()
+    consoleLogging.initialized.store(false)
 
 
-proc shutdownThreadedFileLogging(gls: var GlobalLogServiceObj) =
-  if not gls.file.initialized.load(): return
+proc shutdownThreadedFileLogging() =
+  if not fileLogging.initialized.load(): return
 
-  gls.file.shutdown.store(true) # signal shutdown
+  fileLogging.shutdown.store(true) # signal shutdown
 
-  try: gls.file.chan.send(FileMessage(message: "", absPath: Path("/")))
-  except Exception: discard
+  withLock loggingThreadInitLock:
+    try: fileLogging.chan.send(FileMessage(message: "", absPath: Path("/")))
+    except Exception: discard
 
-  joinThread(gls.file.writerThread)
-  gls.file.chan.close()
-  gls.file.initialized.store(false)
+    joinThread(fileLogging.writerThread)
+    fileLogging.chan.close()
+    fileLogging.initialized.store(false)
 
 
 proc `=destroy`*(gls: var GlobalLogServiceObj) =
   # only one thread should cleanup
   if not gls.initialized.exchange(false): return
 
-  gls.shutdownThreadedConsoleLogging()
-  gls.shutdownThreadedFileLogging()
-
   try: deinitLock(gls.lock)
   except Exception: discard
 
@@ -210,6 +254,28 @@ proc ensureFreshness*(ls: var LogService) =
 proc ensureFreshness*(ls: ThreadLocalLogService) = ensureFreshness(ls[])
 
 
+proc initGlobalLogService(
+    rootLevel = lvlAll,
+    errorHandler = defaultErrorHandlerFunc): GlobalLogService =
+  result = GlobalLogService()
+  result.configVersion.store(0)
+  initLock(result.lock)
+  initLock(result.errorHandlerLock)
+
+  result.appenders = @[]
+  result.thresholds = newTable[string, Level]()
+  result.rootLevel.store(rootLevel)
+  result.errorHandler = errorHandler
+
+  result.initialized.store(true)
+
+proc initLogService(gls: GlobalLogService): LogService =
+  var lsRef: ThreadLocalLogService = ThreadLocalLogService(
+    configVersion: UninitializedConfigVersion, global: gls)
+  ensureFreshness(lsRef)
+  result = lsRef[]
+
+
 proc initLogService*(
     rootLevel = lvlAll,
     errorHandler = defaultErrorHandlerFunc): LogService =
@@ -227,24 +293,12 @@ proc initLogService*(
   ## configure thresholds, and create loggers. The ref returned by this
   ## procedure should also be retained by the main thread so that garbage
   ## collection does not harvest the global state while it is still in use.
-  let global = GlobalLogService()
-  global.configVersion.store(0)
-  global.initialized.store(true)
-  initLock(global.lock)
-  initLock(global.errorHandlerLock)
-
-  global.appenders = @[]
-  global.thresholds = newTable[string, Level]()
-  global.rootLevel.store(rootLevel)
-  global.errorHandler = errorHandler
-
-  var lsRef: ThreadLocalLogService = ThreadLocalLogService(configVersion: -1, global: global)
-  ensureFreshness(lsRef)
-  result = lsRef[]
+  let global = initGlobalLogService(rootLevel, errorHandler)
+  result = initLogService(global)
 
 
 proc threadLocalRef*(ls: LogService): ThreadLocalLogService =
-  result = new(LogService)
+  new result
   result[] = ls
 
 
@@ -337,6 +391,17 @@ proc setThreshold*(ls: ThreadLocalLogService, scope: string, lvl: Level) {.gcsaf
   setThreshold(ls[], scope, lvl)
 
 
+proc setThresholds*(ls: var LogService, thresholds: TableRef[string, Level]) {.gcsafe.} =
+  withLock ls.global.lock:
+    for k,v in thresholds: ls.global.thresholds[k] = v
+    ls.global.configVersion.atomicInc
+
+  ensureFreshness(ls)
+
+
+proc setThresholds*(ls: ThreadLocalLogService, thresholds: TableRef[string, Level]) {.gcsafe.} =
+  setThresholds(ls[], thresholds)
+
 proc getLogger*(
     ls: ThreadLocalLogService,
     scope: string,
@@ -362,6 +427,21 @@ proc getLogger*(
   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.} =
+  for a in ls.appenders: result.add(clone(a))
+
+proc appenders*(ls: ThreadLocalLogService): seq[LogAppender] {.gcsafe.} =
+  ls[].appenders()
+
 proc addAppender*(ls: var LogService, appender: LogAppender) {.gcsafe.} =
   ## Add a log appender to the global log service and refresh the local thread
   ## state. The updated global state will trigger other threads to refresh
@@ -378,6 +458,19 @@ proc addAppender*(ls: ThreadLocalLogService, appender: LogAppender) {.gcsafe.} =
   addAppender(ls[], appender)
 
 
+proc clearAppenders*(ls: var LogService) {.gcsafe.} =
+  ## Remove all log appenders added to the global log service and refresh the
+  ## local thread state. The updated global state will trigger other threads to
+  ## refresh their state as well.
+  withLock ls.global.lock:
+    ls.global.appenders = @[]
+    ls.global.configVersion.atomicInc
+
+
+proc clearAppenders*(ls: ThreadLocalLogService) {.gcsafe.} =
+  clearAppenders(ls[])
+
+
 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
@@ -399,89 +492,173 @@ func getEffectiveThreshold(logger: Logger): Level {.gcsafe.} =
     result = logger.threadSvc.thresholds[namespaces[0]]
 
 
-proc doLog(logger: Logger, msg: LogMessage) {.gcsafe.} =
-  ensureFreshness(logger.threadSvc)
+proc isEnabled*(l: Logger, lvl: Level): bool {.inline,gcsafe.} =
+  lvl >= l.getEffectiveThreshold
 
-  if msg.level < logger.getEffectiveThreshold: return
 
+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)
 
 
-proc log*(l: Logger, lvl: Level, msg: string) {.gcsafe.} =
-  l.doLog(LogMessage(
-    scope: l.scope,
-    level: lvl,
-    error: none[ref Exception](),
-    timestamp: now(),
-    message: msg,
-    additionalData: newJNull()))
+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))
 
 
-proc log*(
-    l: Logger,
+template log*[T: ref Exception](l: Logger, lvl: Level, err: T, 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,
     error: ref Exception,
-    msg: string ) {.gcsafe.} =
-  l.doLog(LogMessage(
-    scope: l.scope,
-    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.scope,
-    level: lvl,
-    error: none[ref Exception](),
-    timestamp: now(),
-    message:
-      if msg.hasKey("message"): msg["message"].getStr
-      else: "",
-    additionalData: msg))
-
-
-proc log*(l: Option[Logger], lvl: Level, msg: string) {.gcsafe.} =
-  if l.isSome: log(l.get, lvl, msg)
-
-proc log*(l: Option[Logger], lvl: Level, msg: JsonNode) {.gcsafe.} =
-  if l.isSome: log(l.get, lvl, msg)
-
-proc log*(l: Option[Logger], lvl: Level, error: ref Exception, msg: string) {.gcsafe.} =
+    msg: untyped) =
   if l.isSome: log(l.get, lvl, error, 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 debug*[L: Logger or Option[Logger], M](l: L, msg: M) =
+  log(l, lvlDebug, msg)
 
-template error*[T](l: Logger, msg: T) = log(l, lvlError, msg)
-template error*(l: Logger, error: ref Exception, msg: string) =
+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 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, error: ref Exception, msg: M) =
   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) =
+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, error: ref Exception, msg: M) =
   log(l, lvlFatal, error, msg)
 
-template debug*[T](l: Option[Logger], msg: T) = log(l, lvlDebug, msg)
-template info*[T](l: Option[Logger], msg: T) = log(l, lvlInfo, msg)
-template notice*[T](l: Option[Logger], msg: T) = log(l, lvlNotice, msg)
-template warn*[T](l: Option[Logger], msg: T) = log(l, lvlWarn, msg)
-
-template error*[T](l: Option[Logger], msg: T) = log(l, lvlError, msg)
-template error*(l: Option[Logger], error: ref Exception, msg: string) =
-  log(l, lvlError, error, msg)
-
-template fatal*[T](l: Option[Logger], msg: T) = log(l, lvlFatal, msg)
-template fatal*(l: Option[Logger], error: ref Exception, msg: string) =
-  log(l, lvlFatal, error, msg)
 
 # -----------------------------------------------------------------------------
-# CustomerLogAppender Implementation
+# Writer Thread Implementations
+# -----------------------------------------------------------------------------
+
+proc consoleWriterLoop() {.thread.} =
+  while not consoleLogging.shutdown.load():
+    var didSomething = false
+
+    let (hasData, msg) = consoleLogging.chan.tryRecv()
+    if hasData and msg.message.len > 0:  # Skip empty sentinel messages
+      try:
+        let output =
+          if msg.useStderr: stderr
+          else: stdout
+        output.write(msg.message)
+        output.flushFile()
+        didSomething = true
+      except IOError:
+        discard
+
+    # Small delay if no work to prevent busy waiting
+    if not didSomething: sleep(100)
+
+
+proc fileWriterLoop() {.thread.} =
+  const bufLen = 128
+  var msgsByPath = newTable[Path, seq[FileMessage]]()
+
+  while not fileLogging.shutdown.load():
+    var didSomething = false
+
+    var msgBuf: array[bufLen, FileMessage]
+    var recvIdx = 0
+    var writeIdx = 0
+    var dataAvailable = true
+
+    while dataAvailable and recvIdx < bufLen:
+      # Fill our message buffer if we can
+      (dataAvailable, msgBuf[recvIdx]) = fileLogging.chan.tryRecv()
+      if dataAvailable: inc recvIdx
+
+    # Organize messages by destination file
+    msgsByPath.clear()
+    while writeIdx < recvIdx:
+      let msg = msgBuf[writeIdx]
+      inc writeIdx
+
+      if msg.message.len > 0:  # skip empty sentinel messages
+        if not msgsByPath.contains(msg.absPath): msgsByPath[msg.absPath] = @[]
+        msgsByPath[msg.absPath].add(msg)
+        didSomething = true
+
+    # 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.message)
+        except Exception: discard
+      flushFile(f)
+      close(f)
+
+    # Wait a bit if we had no work to prevent busy waiting
+    if not didSomething: sleep(100)
+
+
+proc initThreadedConsoleLogging() =
+  if consoleLogging.initialized.load: return
+
+  withLock loggingThreadInitLock:
+    if consoleLogging.initialized.load: return
+    consoleLogging.chan.open()
+    consoleLogging.shutdown.store(false)
+
+    # Create writer thread with reference to the service
+    createThread(consoleLogging.writerThread, consoleWriterLoop)
+    consoleLogging.initialized.store(true)
+
+
+proc initThreadedFileLogging() =
+  if fileLogging.initialized.load: return
+
+  withLock loggingThreadInitLock:
+    if fileLogging.initialized.load: return
+    fileLogging.chan.open()
+    fileLogging.shutdown.store(false)
+
+    # Create writer thread with reference to the service
+    createThread(fileLogging.writerThread, fileWriterLoop)
+    fileLogging.initialized.store(true)
+
+
+# -----------------------------------------------------------------------------
+# CustomLogAppender Implementation
 # -----------------------------------------------------------------------------
 
 func initCustomLogAppender*[T](
@@ -491,7 +668,7 @@ func initCustomLogAppender*[T](
     threshold = lvlAll): CustomLogAppender[T] {.gcsafe.} =
 
   if doLogMessage.isNil:
-    debugEcho "initCustomLogAppender: doLogMessage is nil"
+    raise newException(ValueError, "initCustomLogAppender: doLogMessage is nil")
 
   result = CustomLogAppender[T](
     namespace: namespace,
@@ -500,8 +677,8 @@ func initCustomLogAppender*[T](
     state: state)
 
 method clone*[T](cla: CustomLogAppender[T]): LogAppender {.gcsafe.} =
-  if cla.doLogMessage.isNil:
-    debugEcho "CustomLogAppender#clone: source doLogMessage is nil"
+  assert not cla.doLogMessage.isNil,
+    "CustomLogAppender#clone: source doLogMessage is nil"
 
   result = CustomLogAppender[T](
     namespace: cla.namespace,
@@ -516,7 +693,7 @@ method appendLogMessage[T](
     msg: LogMessage) {.gcsafe.} =
   try:
     if cla.doLogMessage.isNil:
-      debugEcho "doLogMessage is nil"
+      raise newException(ValueError, "CustomLogAppender.appendLogMessage: doLogMessage is nil")
     else: cla.doLogMessage(cla.state, msg)
   except Exception:
     ls.global.reportLoggingError(
@@ -540,41 +717,6 @@ proc initConsoleLogAppender*(
     useStderr: useStderr)
 
 
-proc consoleWriterLoop(gls: GlobalLogService) {.thread.} =
-  while not gls.console.shutdown.load():
-    var didSomething = false
-
-    let (hasData, msg) = gls.console.chan.tryRecv()
-    if hasData and msg.message.len > 0:  # Skip empty sentinel messages
-      try:
-        let output =
-          if msg.useStderr: stderr
-          else: stdout
-        output.write(msg.message)
-        output.flushFile()
-        didSomething = true
-      except IOError:
-        discard
-
-    # Small delay if no work to prevent busy waiting
-    if not didSomething: sleep(100)
-
-
-proc initThreadedConsoleLogging(gls: GlobalLogService) =
-  if gls.console.initialized.load() or  # don't double-init
-     not gls.initialized.load():        # don't init if the gls is shutting down
-    return
-
-  withLock gls.lock:
-    if gls.console.initialized.load(): return
-    gls.console.chan.open()
-    gls.console.shutdown.store(false)
-
-    # Create writer thread with reference to the service
-    createThread(gls.console.writerThread, consoleWriterLoop, gls)
-    gls.console.initialized.store(true)
-
-
 method clone*(cla: ConsoleLogAppender): LogAppender {.gcsafe.} =
   result = ConsoleLogAppender(
     namespace: cla.namespace,
@@ -588,11 +730,11 @@ proc appendLogMessageMultiThreaded(
     ls: ref LogService,
     msg: LogMessage) {.gcsafe.} =
 
-  if not ls.global.console.initialized.load():
-    ls.global.initThreadedConsoleLogging()
+  if not consoleLogging.initialized.load():
+    initThreadedConsoleLogging()
 
   try:
-    ls.global.console.chan.send(ConsoleMessage(
+    consoleLogging.chan.send(ConsoleMessage(
       message: cla.formatter(msg),
       useStderr: cla.useStderr))
   except Exception:
@@ -659,67 +801,6 @@ proc initFileLogAppender*(
     formatter: formatter,
     absPath: absolutePath(Path(filePath)))
 
-  # TODO: initialize global state for the file log writer
-
-
-proc fileWriterLoop(gls: GlobalLogService) {.thread.} =
-  const bufLen = 128
-  var msgsByPath = newTable[Path, seq[FileMessage]]()
-
-  while not gls.file.shutdown.load():
-    var didSomething = false
-
-    var msgBuf: array[bufLen, FileMessage]
-    var recvIdx = 0
-    var writeIdx = 0
-    var dataAvailable = true
-
-    while dataAvailable and recvIdx < bufLen:
-      # Fill our message buffer if we can
-      (dataAvailable, msgBuf[recvIdx]) = gls.file.chan.tryRecv()
-      if dataAvailable: inc recvIdx
-
-    # Organize messages by destination file
-    msgsByPath.clear()
-    while writeIdx < recvIdx:
-      let msg = msgBuf[writeIdx]
-      inc writeIdx
-
-      if msg.message.len > 0:  # skip empty sentinel messages
-        if not msgsByPath.contains(msg.absPath): msgsByPath[msg.absPath] = @[]
-        msgsByPath[msg.absPath].add(msg)
-        didSomething = true
-
-    # 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.message)
-        except Exception: discard
-      flushFile(f)
-      close(f)
-
-    # Wait a bit if we had no work to prevent busy waiting
-    if not didSomething: sleep(100)
-
-
-proc initThreadedFileLogging(gls: GlobalLogService) =
-  if gls.file.initialized.load(): return
-
-  withLock gls.lock:
-    if gls.file.initialized.load(): return
-    gls.file.chan.open()
-    gls.file.shutdown.store(false)
-
-    # Create writer thread with reference to the service
-    createThread(gls.file.writerThread, fileWriterLoop, gls)
-    gls.file.initialized.store(true)
-
 
 method clone*(fla: FileLogAppender): LogAppender {.gcsafe.} =
   result = FileLogAppender(
@@ -734,11 +815,11 @@ proc appendLogMessageMultiThreaded(
     ls: ref LogService,
     msg: LogMessage) {.gcsafe.} =
 
-  if not ls.global.file.initialized.load():
-    ls.global.initThreadedFileLogging()
+  if not fileLogging.initialized.load():
+    initThreadedFileLogging()
 
   try:
-    ls.global.file.chan.send(FileMessage(
+    fileLogging.chan.send(FileMessage(
       message: fla.formatter(msg),
       absPath: fla.absPath))
   except Exception: discard
@@ -774,14 +855,66 @@ method appendLogMessage(
       "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)
+
+
+func initStdLoggingAppender*(
+    fallbackOnly = true,
+    formatter = formatForwardedLog,
+    namespace = "",
+    threshold = lvlAll): StdLoggingAppender {.gcsafe.} =
+
+  result = StdLoggingAppender(
+    namespace: namespace,
+    threshold: threshold,
+    fallbackOnly: fallbackOnly,
+    formatter: formatter)
+
+
+method clone*(sla: StdLoggingAppender): LogAppender {.gcsafe.} =
+  result = StdLoggingAppender(
+    namespace: sla.namespace,
+    threshold: sla.threshold,
+    fallbackOnly: sla.fallbackOnly,
+    formatter: 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(msg))
+
+
+# -----------------------------------------------------------------------------
+# Cleanup
+# -----------------------------------------------------------------------------
+
+addExitProc(proc() =
+  shutdownThreadedConsoleLogging()
+  shutdownThreadedFileLogging()
+)
+
+
+# -----------------------------------------------------------------------------
+# Tests
+# -----------------------------------------------------------------------------
 
 when isMainModule:
 
-  import std/[tempfiles, unittest]
+  import std/[files, tempfiles, unittest]
   import ./namespaced_logging/testutil
-  # -----------------------------------------------------------------------------
-  # Tests
-  # -----------------------------------------------------------------------------
 
   suite "GlobalLogService Initialization":
 
@@ -905,8 +1038,7 @@ when isMainModule:
     setup:
       let ls = threadLocalRef(initLogService())
       let loggedMsgs = initLoggedMessages()
-      let testAppender = initTestLogAppender(loggedMsgs)
-      ls.addAppender(testAppender)
+      ls.addAppender(initTestLogAppender(loggedMsgs))
 
     test "getLogger creates logger with correct scope":
       let logger = ls.getLogger("api/users")
@@ -916,6 +1048,26 @@ when isMainModule:
       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, %*{"message": "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].message.contains("debug string msg")
+        lm[1].level == lvlInfo
+        lm[1].message.contains("info json msg")
+        lm[2].level == lvlNotice
+        lm[2].message.contains("notice string msg")
+        lm[3].level == lvlError
+        lm[3].message.contains("error ex. msg")
+
     test "logger convenience methods work":
       let logger = ls.getLogger("test")
 
@@ -964,8 +1116,7 @@ when isMainModule:
     setup:
       let ls = threadLocalRef(initLogService())
       let loggedMsgs = initLoggedMessages()
-      let testAppender = initTestLogAppender(loggedMsgs)
-      ls.addAppender(testAppender)
+      ls.addAppender(initTestLogAppender(loggedMsgs))
 
     test "root level filtering":
       ls.setRootThreshold(lvlInfo)
@@ -1015,6 +1166,25 @@ when isMainModule:
         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].message.contains("Expensive call (1)")
+        expensiveCallCount == 1
+
   suite "Appender Functionality":
     setup:
       let ls = threadLocalRef(initLogService())
@@ -1113,6 +1283,8 @@ when isMainModule:
         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)
@@ -1121,3 +1293,107 @@ when isMainModule:
       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].message.contains("message at notice")
+        lm[1].message.contains("message at warn")
+        lm[2].message.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].message.contains("message at notice")
+        lm[1].message.contains("message at warn")
+        lm[2].message.contains("message at fatal")

src/namespaced_logging/autoconfigured.nim

@@ -1,98 +0,0 @@
-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"