diff --git a/namespaced_logging.nimble b/namespaced_logging.nimble index 539c72e..89469f7 100644 --- a/namespaced_logging.nimble +++ b/namespaced_logging.nimble @@ -13,3 +13,8 @@ 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 src/namespaced_logging/autoconfigured.nim" + exec "src/namespaced_logging.out" + exec "src/namespaced_logging/autoconfigured" diff --git a/src/namespaced_logging.nim b/src/namespaced_logging.nim index 6380d4d..58a0e62 100644 --- a/src/namespaced_logging.nim +++ b/src/namespaced_logging.nim @@ -998,13 +998,14 @@ proc resetAutoconfiguredLogging*() = autoGls = GlobalLogService() initAutoconfiguredLogService() +# ----------------------------------------------------------------------------- +# Tests +# ----------------------------------------------------------------------------- + when isMainModule: - import std/[tempfiles, unittest] + import std/[files, tempfiles, unittest] import ./namespaced_logging/testutil - # ----------------------------------------------------------------------------- - # Tests - # ----------------------------------------------------------------------------- suite "GlobalLogService Initialization": @@ -1128,8 +1129,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") @@ -1139,6 +1139,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") @@ -1187,8 +1207,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) @@ -1365,3 +1384,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") diff --git a/src/namespaced_logging/autoconfigured.nim b/src/namespaced_logging/autoconfigured.nim index 5a706b9..54286b9 100644 --- a/src/namespaced_logging/autoconfigured.nim +++ b/src/namespaced_logging/autoconfigured.nim @@ -62,18 +62,159 @@ when isMainModule: import std/unittest import ./testutil - suite "Autoconfigured Logging": - setup: - globalLogServiceRef[] = initLogService() - let loggedMessages = initLoggedMessages() - let testAppender = initTestLogAppender(loggedMessages) + suite "Automatic Global Setup": - test "simple no-config logging": - addLogAppender(testAppender) + setup: + clearLogAppenders() + let loggedMsgs = initLoggedMessages() + addLogAppender(initTestLogAppender(loggedMsgs)) + # note that we are not resetting the global log service reference as the + # module default behavior in setting up the global log service reference + # is what we want to test + + test "simple logging works": info("test message") - let lm = loggedMessages.get() + let lm = loggedMsgs.get() check: lm.len == 1 lm[0].level == lvlInfo lm[0].message == "test message" + lm[0].scope == "" + + suite "Autoconfigured Logging": + setup: + resetAutoconfiguredLogging() + let loggedMsgs = initLoggedMessages() + addLogAppender(initTestLogAppender(loggedMsgs)) + + test "message construction is avoided if the message is not logged": + var expensiveCallCount = 0 + proc expensiveCall(): int = + inc expensiveCallCount + return expensiveCallCount + + setRootLoggingThreshold(lvlInfo) + + debug("Expensive call (" & $expensiveCall() & ")") + info("Expensive call (" & $expensiveCall() & ")") + + let lm = loggedMsgs.get() + check: + lm.len == 1 + lm[0].message.contains("Expensive call (1)") + expensiveCallCount == 1 + + test "thread local variables are cached": + # Get the service reference multiple times - should be same instance + let svc1 = getAutoconfiguredLogService() + let svc2 = getAutoconfiguredLogService() + check svc1 == svc2 + + # Default logger should also be cached + let logger1 = getAutoconfiguredLogger() + let logger2 = getAutoconfiguredLogger() + check logger1 == logger2 + + test "logging with exceptions works": + let testException = newException(ValueError, "test error") + error(testException, "Something went wrong") + + let lm = loggedMsgs.get() + check: + lm.len == 1 + lm[0].level == lvlError + lm[0].error.isSome + lm[0].error.get.msg == "test error" + + test "all convenience methods work": + debug("debug message") + info("info message") + notice("notice message") + warn("warn message") + error("error message") + 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 "message construction is avoided if the message is not logged": + var expensiveCallCount = 0 + proc expensiveCall(): int = + inc expensiveCallCount + return expensiveCallCount + + setRootLoggingThreshold(lvlInfo) + + debug("Expensive call (" & $expensiveCall() & ")") + info("Expensive call (" & $expensiveCall() & ")") + + let lm = loggedMsgs.get() + check: + lm.len == 1 + lm[0].message.contains("Expensive call (1)") + expensiveCallCount == 1 + + + suite "Global Service Management": + setup: + resetAutoconfiguredLogging() + + test "useForAutoconfiguredLogging changes global service": + + let origLogs = initLoggedMessages() + let newLogs = initLoggedMessages() + + # autoconfiged first + addLogAppender(initTestLogAppender(origLogs)) + let origLogger = getAutoconfiguredLogger() + debug("msg 1") + + # Then we setup a custom service that will take over the autoconfig + var customLogService = initLogService(lvlWarn) + customLogService.addAppender(initTestLogAppender(newLogs)) + useForAutoconfiguredLogging(customLogService) + + # Subsequent calls to debug, info, etc. should use the new config + debug("msg 2 - should be filtered") + warn("msg 3 - should appear") + + # Any Loggers that are still around should also get updates + origLogger.debug("msg 4 - should be filtered") + origLogger.error("msg 5 - should appear") + + let lmOrig = origLogs.get() + let lmNew = newLogs.get() + check: + lmOrig.len == 1 + lmOrig[0].message == "msg 1" + lmNew.len == 2 + lmNew[0].message == "msg 3 - should appear" + lmNew[1].message == "msg 5 - should appear" + + test "configuration changes affect autoconfigured logging": + let loggedMsgs = initLoggedMessages() + addLogAppender(initTestLogAppender(loggedMsgs)) + + # Initially all levels should work + debug("debug message") + + # Change root threshold + setRootLoggingThreshold(lvlInfo) + + # Debug should now be filtered + debug("should be filtered") + info("should appear") + + let lm = loggedMsgs.get() + check: + lm.len == 2 # First debug + info + lm[0].level == lvlDebug + lm[1].level == lvlInfo