diff --git a/README.md b/README.md index 1ee93ec..f78c8b3 100644 --- a/README.md +++ b/README.md @@ -133,6 +133,11 @@ the same manner to loggers in this library. ### LogFormatter +Messages created by the library carry UTC timestamps in `LogMessage.ts`, which +remains a `DateTime`. This changes the previous local-time behavior. Structured +JSON output represents these timestamps with a `Z` suffix. Explicit timestamps +in caller-constructed `LogMessage` values are preserved. + Console, file, and std/logging appenders accept a *LogFormatter*. Noncapturing functions such as *formatSimpleTextLog* and *formatJsonStructuredLog* are converted automatically: @@ -342,9 +347,8 @@ not refresh configuration; see [Avoiding Expensive Log Preparation](#avoiding-ex > [!NOTE] > Thread-safety work is still in progress. Custom state and captured -> formatters must follow the ownership rules above. Concurrent local-time -> timestamp construction still has a known failure. -> Nim 2.2.10 also produces sanitizer reports in its default allocator +> formatters must follow the ownership rules above. +> Nim 2.2.10 produces sanitizer reports in its default allocator > during some cross-thread allocation patterns. See > [the regression tests](tests/README.md) for the remaining work. diff --git a/src/namespaced_logging.nim b/src/namespaced_logging.nim index 4cb837f..0999b5d 100644 --- a/src/namespaced_logging.nim +++ b/src/namespaced_logging.nim @@ -73,6 +73,7 @@ type level*: Level err*: Option[ref Exception] ts*: DateTime + ## initLogMessage records the current instant in UTC. msg*: string additionalData*: JsonNode @@ -217,12 +218,13 @@ proc initLogMessage*( msg: string, err: Option[ref Exception] = none[ref Exception](), additionalData: JsonNode = newJNull()): LogMessage = + ## Create a message with a UTC timestamp, avoiding local-time conversion. LogMessage( scope: scope, level: lvl, err: err, - ts: now(), + ts: getTime().utc, msg: msg, additionalData: additionalData) @@ -232,12 +234,13 @@ proc initLogMessage*( lvl: Level, msg: JsonNode, err: Option[ref Exception] = none[ref Exception]()): LogMessage = + ## Create a structured message with a UTC timestamp. LogMessage( scope: scope, level: lvl, err: err, - ts: now(), + ts: getTime().utc, msg: if msg.hasKey("msg"): msg["msg"].getStr elif msg.hasKey("message"): msg["message"].getStr diff --git a/tests/README.md b/tests/README.md index 397f6a5..916eb45 100644 --- a/tests/README.md +++ b/tests/README.md @@ -54,9 +54,11 @@ checks that each worker maintains its own counter. `collector` concurrently records messages containing JSON and exceptions and mutates returned snapshots. These ownership scenarios use explicit timestamps where messages are needed. -The separate `timestamp` case exercises concurrent `initLogMessage()` calls. It -currently exposes a sanitizer report in libc local-time conversion reached via -Nim's `std/times.now()`; this remains a separate thread-safety issue. +The separate `timestamp` case exercises both `initLogMessage()` overloads and +structured JSON formatting concurrently. Generated timestamps use UTC, avoiding +the libc local-time conversion race previously reached via `std/times.now()`. +The timestamp regressions verify the captured instant, UTC timezone, and `Z` +suffix in structured output. `allocator` calls the standalone reproduction in `runtime_allocator.nim`, which imports no logging code. It exercises sequence growth and clearing under a lock @@ -117,9 +119,8 @@ The suite provides targeted regressions; it does not exhaust thread scheduling or ORC cycle-collector interleavings. The ownership scenarios, lifetime suite, and appender-state cleanup regression -exercise the new ownership contracts. Local-time timestamp construction and -allocator reports remain for -subsequent work. +exercise the new ownership contracts. Allocator reports remain for subsequent +work. The standalone `ownership.nim` regression suite passed AddressSanitizer and LeakSanitizer with `--mm:orc -d:useMalloc`. An additional worker-thread build found diff --git a/tests/regressions.nim b/tests/regressions.nim index cbd5fb6..6b7733f 100644 --- a/tests/regressions.nim +++ b/tests/regressions.nim @@ -1,7 +1,27 @@ -import std/[os, osproc, strutils, tempfiles, unittest] +import std/[json, os, osproc, strutils, tempfiles, times, unittest] import ../src/namespaced_logging import ./ownership +suite "Log message timestamps": + test "both constructors capture the current instant in UTC": + let before = getTime() + let textMessage = initLogMessage("timestamp", lvlInfo, "text") + let jsonMessage = initLogMessage("timestamp", lvlInfo, %*{"msg": "json"}) + let after = getTime() + for message in [textMessage, jsonMessage]: + check message.ts.timezone.name == "Etc/UTC" + check message.ts.utcOffset == 0 + check not message.ts.isDst + check message.ts.toTime >= before + check message.ts.toTime <= after + + test "structured output represents generated timestamps in UTC": + for message in [initLogMessage("timestamp", lvlInfo, "text"), + initLogMessage("timestamp", lvlInfo, %*{"msg": "json"})]: + let encoded = parseJson(formatJsonStructuredLog(message))["ts"].getStr + check encoded == message.ts.format("yyyy-MM-dd'T'HH:mm:sszzz") + check encoded.endsWith("Z") + type CloneControl = object failNext: bool diff --git a/tests/thread_safety.nim b/tests/thread_safety.nim index 9e391ae..1c9ed8e 100644 --- a/tests/thread_safety.nim +++ b/tests/thread_safety.nim @@ -158,8 +158,13 @@ proc factoryWorker(source: ptr LogService) {.thread.} = proc timestampWorker() {.thread.} = awaitStart() for i in 0 ..< iterations: - let msg = initLogMessage("worker", lvlInfo, "message") - doAssert msg.msg == "message" + for msg in [initLogMessage("worker", lvlInfo, "message"), + initLogMessage("worker", lvlInfo, %*{"msg": "message"})]: + doAssert msg.msg == "message" + doAssert msg.ts.timezone.name == "Etc/UTC" + doAssert msg.ts.utcOffset == 0 + doAssert not msg.ts.isDst + doAssert parseJson(formatJsonStructuredLog(msg))["ts"].getStr.len > 0 proc collectorWorker(collector: LoggedMessages) {.thread.} = # Construct every managed field in this worker, including the timezone. diff --git a/tests/writer_child.nim b/tests/writer_child.nim index 0b63ad6..f97b4bd 100644 --- a/tests/writer_child.nim +++ b/tests/writer_child.nim @@ -12,9 +12,7 @@ proc formatOptionalLine(msg: LogMessage): string {.gcsafe.} = proc writeMessages(args: tuple[service: LogService, worker: int]) {.thread.} = let logger = args.service.threadLocalRef().getLogger("shutdown") for i in 0 ..< 2_500: - # Keep the timestamp race out of this writer lifecycle test. - logger.log(LogMessage(scope: "shutdown", level: lvlInfo, - msg: "message " & $(args.worker * 2_500 + i))) + logger.info("message " & $(args.worker * 2_500 + i)) proc main() = doAssert paramCount() == 2