Create log timestamps in UTC to avoid local-time races

Use getTime().utc in both message constructors, document the timezone change, and cover concurrent construction and structured formatting. Restore ordinary logging calls in the parallel writer fixture.

Validation: 32 unit tests and 29 regression tests pass. Timestamp sanitizer checks pass under UTC and non-UTC timezones. The full suite retains the known allocator reports in factory-state and allocator.

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
+> formatters must follow the ownership rules above.
-> timestamp construction still has a known failure.
+> Nim 2.2.10 produces sanitizer reports in its default allocator
-> Nim 2.2.10 also produces sanitizer reports in its default allocator
 > during some cross-thread allocation patterns. See
 > [the regression tests](tests/README.md) for the remaining work.
 

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

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
+The separate `timestamp` case exercises both `initLogMessage()` overloads and
-currently exposes a sanitizer report in libc local-time conversion reached via
+structured JSON formatting concurrently. Generated timestamps use UTC, avoiding
-Nim's `std/times.now()`; this remains a separate thread-safety issue.
+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
+exercise the new ownership contracts. Allocator reports remain for subsequent
-allocator reports remain for
+work.
-subsequent work.
 
 The standalone `ownership.nim` regression suite passed AddressSanitizer and
 LeakSanitizer with `--mm:orc -d:useMalloc`. An additional worker-thread build found

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

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")
+    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.

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.info("message " & $(args.worker * 2_500 + i))
-    logger.log(LogMessage(scope: "shutdown", level: lvlInfo,
-      msg: "message " & $(args.worker * 2_500 + i)))
 
 proc main() =
   doAssert paramCount() == 2