impr: Add timeIntervalSince1970 to SDK log messages (#4781)

Add the system uptime to the SDK log messages to know precisely when the logger logs. This can help when investigating issues by reading the SDK log messages.
getsentry · Feb 7, 2025 · a03f232 · a03f232
1 parent 421cd69
commit a03f232
Show file tree

Hide file tree

Showing 4 changed files with 36 additions and 10 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -12,6 +12,7 @@
 
 - Add more debug logs for SentryViewHierarchy (#4780)
 - Add `sample_rand` to baggage (#4751)
+- Add timeIntervalSince1970 to log messages (#4781)
 - Add `waitForFullDisplay` to `sentryTrace` view modifier (#4797)
 
 ### Fixes

diff --git a/Sources/Swift/Tools/SentryLog.swift b/Sources/Swift/Tools/SentryLog.swift
@@ -13,6 +13,7 @@ class SentryLog: NSObject {
     static let alwaysLevel = SentryLevel.fatal
     private static var logOutput = SentryLogOutput()
     private static var logConfigureLock = NSLock()
+    private static var dateProvider: SentryCurrentDateProvider = SentryDefaultCurrentDateProvider()
 
     @objc
     static func configure(_ isDebug: Bool, diagnosticLevel: SentryLevel) {
@@ -26,7 +27,13 @@ class SentryLog: NSObject {
     @objc
     static func log(message: String, andLevel level: SentryLevel) {
         guard willLog(atLevel: level) else { return }
-        logOutput.log("[Sentry] [\(level)] \(message)")
+
+        // We use the timeIntervalSinceReferenceDate because date format is
+        // expensive and we only care about the time difference between the
+        // log messages. We don't use system uptime because of privacy concerns
+        // see: NSPrivacyAccessedAPICategorySystemBootTime.
+        let time = self.dateProvider.date().timeIntervalSince1970
+        logOutput.log("[Sentry] [\(level)] [timeIntervalSince1970:\(time)] \(message)")
     }
 
     /**
@@ -54,6 +61,10 @@ class SentryLog: NSObject {
         return logOutput
     }
 
+    static func setDateProvider(_ dateProvider: SentryCurrentDateProvider) {
+        self.dateProvider = dateProvider
+    }
+
     #endif
 }
 

diff --git a/Tests/SentryTests/Helper/SentryLog.swift b/Tests/SentryTests/Helper/SentryLog.swift
@@ -21,4 +21,10 @@ extension Sentry.SentryLog {
         SentryLogOutput()
         #endif
     }
+
+    static func setCurrentDateProvider(_ dateProvider: SentryCurrentDateProvider) {
+        #if SENTRY_TEST || SENTRY_TEST_CI
+        SentryLog.setDateProvider(dateProvider)
+        #endif
+    }
 }
diff --git a/Tests/SentryTests/Helper/SentryLogTests.swift b/Tests/SentryTests/Helper/SentryLogTests.swift
@@ -6,18 +6,26 @@ class SentryLogTests: XCTestCase {
     private var oldDebug: Bool!
     private var oldLevel: SentryLevel!
     private var oldOutput: SentryLogOutput!
+    private var timeIntervalSince1970: TimeInterval = 0.0
 
     override func setUp() {
         super.setUp()
         oldDebug = SentryLog.isDebug
         oldLevel = SentryLog.diagnosticLevel
         oldOutput = SentryLog.getLogOutput()
+
+        let currentDateProvider = TestCurrentDateProvider()
+        currentDateProvider.advance(by: 0.1234)
+        timeIntervalSince1970 = currentDateProvider.date().timeIntervalSince1970
+
+        SentryLog.setCurrentDateProvider(currentDateProvider)
     }
 
     override func tearDown() {
         super.tearDown()
         SentryLog.configure(oldDebug, diagnosticLevel: oldLevel)
         SentryLog.setLogOutput(oldOutput)
+        SentryLog.setCurrentDateProvider(SentryDefaultCurrentDateProvider())
     }
 
     func testDefault_PrintsFatalAndError() {
@@ -30,7 +38,7 @@ class SentryLogTests: XCTestCase {
         SentryLog.log(message: "2", andLevel: SentryLevel.warning)
         SentryLog.log(message: "3", andLevel: SentryLevel.none)
 
-        XCTAssertEqual(["[Sentry] [fatal] 0", "[Sentry] [error] 1"], logOutput.loggedMessages)
+        XCTAssertEqual(["[Sentry] [fatal] [timeIntervalSince1970:\(timeIntervalSince1970)] 0", "[Sentry] [error] [timeIntervalSince1970:\(timeIntervalSince1970)] 1"], logOutput.loggedMessages)
     }
 
     func testDefaultInitOfLogoutPut() {
@@ -53,7 +61,7 @@ class SentryLogTests: XCTestCase {
 
         // -- Assert --
         XCTAssertEqual(1, logOutput.loggedMessages.count)
-        XCTAssertEqual("[Sentry] [fatal] fatal", logOutput.loggedMessages.first)
+        XCTAssertEqual("[Sentry] [fatal] [timeIntervalSince1970:\(timeIntervalSince1970)] fatal", logOutput.loggedMessages.first)
     }
 
     func testLevelNone_PrintsEverythingExceptNone() {
@@ -68,11 +76,11 @@ class SentryLogTests: XCTestCase {
         SentryLog.log(message: "4", andLevel: SentryLevel.debug)
         SentryLog.log(message: "5", andLevel: SentryLevel.none)
 
-        XCTAssertEqual(["[Sentry] [fatal] 0",
-                        "[Sentry] [error] 1",
-                        "[Sentry] [warning] 2",
-                        "[Sentry] [info] 3",
-                        "[Sentry] [debug] 4"], logOutput.loggedMessages)
+        XCTAssertEqual(["[Sentry] [fatal] [timeIntervalSince1970:\(timeIntervalSince1970)] 0",
+                        "[Sentry] [error] [timeIntervalSince1970:\(timeIntervalSince1970)] 1",
+                        "[Sentry] [warning] [timeIntervalSince1970:\(timeIntervalSince1970)] 2",
+                        "[Sentry] [info] [timeIntervalSince1970:\(timeIntervalSince1970)] 3",
+                        "[Sentry] [debug] [timeIntervalSince1970:\(timeIntervalSince1970)] 4"], logOutput.loggedMessages)
     }
 
     func testMacroLogsErrorMessage() {
@@ -82,7 +90,7 @@ class SentryLogTests: XCTestCase {
 
         sentryLogErrorWithMacro("error")
 
-        XCTAssertEqual(["[Sentry] [error] [SentryLogTestHelper:20] error"], logOutput.loggedMessages)
+        XCTAssertEqual(["[Sentry] [error] [timeIntervalSince1970:\(timeIntervalSince1970)] [SentryLogTestHelper:20] error"], logOutput.loggedMessages)
     }
 
     func testMacroDoesNotEvaluateArgs_WhenNotMessageNotLogged() {
@@ -101,7 +109,7 @@ class SentryLogTests: XCTestCase {
         SentryLog.configure(true, diagnosticLevel: SentryLevel.debug)
         let line = #line + 1
         SentryLog.debug("Debug Log")
-        XCTAssertEqual(["[Sentry] [debug] [SentryLogTests:\(line)] Debug Log"], logOutput.loggedMessages)
+        XCTAssertEqual(["[Sentry] [debug] [timeIntervalSince1970:\(timeIntervalSince1970)] [SentryLogTests:\(line)] Debug Log"], logOutput.loggedMessages)
     }
 
 }