Add millisecond precision to StreamLogHandler timestamp

Sources/Logging/Handlers/StreamLogHandler.swift

@@ -212,26 +212,54 @@ public struct StreamLogHandler: LogHandler {
 
     private func timestamp() -> String {
         var buffer = [Int8](repeating: 0, count: 255)
+        var tzBuffer = [Int8](repeating: 0, count: 16)
+        let ms: Int
         #if os(Windows)
-        var timestamp = __time64_t()
-        _ = _time64(&timestamp)
-
+        // Use _ftime64_s for millisecond-precision wall-clock time on Windows.
+        var tb = __timeb64()
+        _ = _ftime64_s(&tb)
         var localTime = tm()
-        _ = _localtime64_s(&localTime, &timestamp)
-
-        _ = strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S%z", &localTime)
-        #else
+        _ = _localtime64_s(&localTime, &tb.time)
+        _ = strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S", &localTime)
+        _ = strftime(&tzBuffer, tzBuffer.count, "%z", &localTime)
+        ms = Int(tb.millitm)
+        #elseif canImport(WASILibc)
+        // WASI does not expose CLOCK_REALTIME as a Swift-importable constant
+        // (it is defined as a pointer-to-struct macro, which Swift cannot import).
+        // Fall back to time(nil) which gives second-level precision on WASI.
         var timestamp = time(nil)
         guard let localTime = localtime(&timestamp) else {
             return "<unknown>"
         }
-        strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S%z", localTime)
+        strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S", localTime)
+        strftime(&tzBuffer, tzBuffer.count, "%z", localTime)
+        ms = 0
+        #else
+        // Use clock_gettime for sub-second precision (milliseconds).
+        var ts = timespec()
+        clock_gettime(CLOCK_REALTIME, &ts)
+        guard let localTime = localtime(&ts.tv_sec) else {
+            return "<unknown>"
+        }
+        // Format date+time and timezone separately so we can inject milliseconds.
+        strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S", localTime)
+        strftime(&tzBuffer, tzBuffer.count, "%z", localTime)
+        ms = Int(ts.tv_nsec) / 1_000_000
         #endif
-        return buffer.withUnsafeBufferPointer {
+        let dateStr = buffer.withUnsafeBufferPointer {
+            $0.withMemoryRebound(to: CChar.self) {
+                String(cString: $0.baseAddress!)
+            }
+        }
+        let tzStr = tzBuffer.withUnsafeBufferPointer {
             $0.withMemoryRebound(to: CChar.self) {
                 String(cString: $0.baseAddress!)
             }
         }
+        // Zero-pad milliseconds to 3 digits without requiring Foundation.
+        let msStr: String
+        if ms < 10 { msStr = "00\(ms)" } else if ms < 100 { msStr = "0\(ms)" } else { msStr = "\(ms)" }
+        return "\(dateStr).\(msStr)\(tzStr)"
     }
 }
 

Tests/LoggingTests/StreamLogHandlerTest.swift

@@ -73,7 +73,7 @@ struct StreamLogHandlerTest {
         log.critical("\(testString)", source: source)
 
         let pattern =
-            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label):\\s\\[\(source)\\]\\s\(testString)$"
+            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\.\\d{3})?(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label):\\s\\[\(source)\\]\\s\(testString)$"
 
         let messageSucceeded =
             interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).range(
@@ -99,7 +99,7 @@ struct StreamLogHandlerTest {
         log.critical("\(testString)", source: source)
 
         let pattern =
-            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\+|-)\\d{4}\\s\(Logger.Level.critical):\\s\\[\(source)\\]\\s\(testString)$"
+            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\.\\d{3})?(\\+|-)\\d{4}\\s\(Logger.Level.critical):\\s\\[\(source)\\]\\s\(testString)$"
 
         let messageSucceeded =
             interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).range(
@@ -126,7 +126,7 @@ struct StreamLogHandlerTest {
         log.critical("\(testString)", metadata: ["test": "test"], source: source)
 
         let pattern =
-            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label):\\stest=test\\s\\[\(source)\\]\\s\(testString)$"
+            "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(\\.\\d{3})?(\\+|-)\\d{4}\\s\(Logger.Level.critical)\\s\(label):\\stest=test\\s\\[\(source)\\]\\s\(testString)$"
 
         let messageSucceeded =
             interceptStream.interceptedText?.trimmingCharacters(in: .whitespacesAndNewlines).range(
@@ -295,9 +295,6 @@ struct StreamLogHandlerTest {
         var err = setvbuf(writeFD, writeBuffer, _IOFBF, 256)
         #expect(err == 0, "setvbuf failed \(err)")
 
-        // Create the stream here while writeFD's concrete type is in scope.
-        // Type inference in the generic StdioOutputStream init picks the right
-        // C functions for whatever FILE representation this platform/API level uses.
         #if os(Windows)
         let stream = StdioOutputStream(
             file: writeFD,

Tests/LoggingTests/StreamLogHandlerTimestampTests.swift

@@ -0,0 +1,114 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the Swift Logging API open source project
+//
+// Copyright (c) 2018-2019 Apple Inc. and the Swift Logging API project authors
+// Licensed under Apache License v2.0
+//
+// See LICENSE.txt for license information
+// See CONTRIBUTORS.txt for the list of Swift Logging API project authors
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+//===----------------------------------------------------------------------===//
+
+import Testing
+
+@testable import Logging
+
+// A simple in-memory stream for capturing log output in tests.
+private final class CapturingStream: TextOutputStream, @unchecked Sendable {
+    private(set) var output = ""
+    func write(_ string: String) { output += string }
+}
+
+@Suite("StreamLogHandler timestamp tests")
+struct StreamLogHandlerTimestampTests {
+    // Helper: emit one log line and return the timestamp field (the first space-delimited token).
+    private func captureTimestamp() -> String {
+        let stream = CapturingStream()
+        let handler = StreamLogHandler(label: "ts-test", stream: stream)
+        var logger = Logger(label: "ts-test", factory: { _ in handler })
+        logger.logLevel = .info
+        logger.info("probe")
+        let firstLine = stream.output.split(separator: "\n", omittingEmptySubsequences: false).first ?? ""
+        return String(firstLine.split(separator: " ").first ?? "")
+    }
+
+    @Test("Timestamp includes a millisecond component")
+    func timestampContainsMilliseconds() {
+        let ts = captureTimestamp()
+        #expect(!ts.isEmpty, "log output should not be empty")
+        #expect(ts.contains("."), "timestamp '\(ts)' should include a millisecond separator")
+    }
+
+    @Test("Millisecond component is exactly 3 digits")
+    func timestampMillisecondsAreThreeDigits() {
+        let ts = captureTimestamp()
+        guard let dotIdx = ts.firstIndex(of: ".") else {
+            Issue.record("no '.' found in timestamp '\(ts)'")
+            return
+        }
+        let msDigits = ts[ts.index(after: dotIdx)...].prefix(3)
+        #expect(
+            msDigits.count == 3 && msDigits.allSatisfy { $0.isNumber },
+            "expected 3-digit millisecond field in '\(ts)', got '\(msDigits)'"
+        )
+    }
+
+    @Test("Millisecond value is in valid range [0, 999]")
+    func timestampMillisecondsAreInRange() {
+        let ts = captureTimestamp()
+        guard let dotIdx = ts.firstIndex(of: ".") else {
+            Issue.record("no '.' found in timestamp '\(ts)'")
+            return
+        }
+        let msString = String(ts[ts.index(after: dotIdx)...].prefix(3))
+        guard let ms = Int(msString) else {
+            Issue.record("could not parse milliseconds from '\(ts)'")
+            return
+        }
+        #expect(ms >= 0 && ms <= 999, "milliseconds \(ms) are out of range [0, 999]")
+    }
+
+    @Test("Multiple log calls each produce a correctly formatted timestamp")
+    func multipleTimestampsAreAllWellFormed() {
+        let stream = CapturingStream()
+        let handler = StreamLogHandler(label: "ts-test", stream: stream)
+        var logger = Logger(label: "ts-test", factory: { _ in handler })
+        logger.logLevel = .info
+        logger.info("first")
+        logger.info("second")
+        logger.info("third")
+
+        let lines = stream.output.split(separator: "\n").filter { !$0.isEmpty }
+        #expect(lines.count == 3, "expected exactly 3 log lines")
+
+        for line in lines {
+            let ts = String(line.split(separator: " ").first ?? "")
+            #expect(ts.contains("."), "timestamp '\(ts)' should have a millisecond separator")
+            if let dotIdx = ts.firstIndex(of: ".") {
+                let msDigits = ts[ts.index(after: dotIdx)...].prefix(3)
+                #expect(
+                    msDigits.count == 3 && msDigits.allSatisfy { $0.isNumber },
+                    "timestamp '\(ts)' has malformed milliseconds"
+                )
+            }
+        }
+    }
+
+    @Test("Timestamp has expected ISO 8601 structure")
+    func timestampStructureMatchesISO8601() {
+        let ts = captureTimestamp()
+        let tParts = ts.split(separator: "T")
+        #expect(tParts.count == 2, "timestamp '\(ts)' should contain exactly one 'T' separator")
+        if tParts.count == 2 {
+            let datePart = tParts[0]
+            let timePart = tParts[1]
+            let dateSections = datePart.split(separator: "-")
+            #expect(dateSections.count == 3, "date '\(datePart)' should have 3 dash-separated sections")
+            #expect(timePart.contains(":"), "time '\(timePart)' should contain colons")
+            #expect(timePart.contains("."), "time '\(timePart)' should contain a millisecond dot")
+        }
+    }
+}