Browse Source

Add the concept of a correlation ID to NSE logging

Sasha Weiss 2 months ago
parent
commit
ac05bfc690

+ 4 - 0
Signal.xcodeproj/project.pbxproj

@@ -1057,6 +1057,7 @@
 		D221A0E8169DFFC500537ABF /* AVFoundation.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = D221A0E7169DFFC500537ABF /* AVFoundation.framework */; };
 		D24B5BD5169F568C00681372 /* AudioToolbox.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = D24B5BD4169F568C00681372 /* AudioToolbox.framework */; };
 		D2AEACDC16C426DA00C364C0 /* CFNetwork.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = D2AEACDB16C426DA00C364C0 /* CFNetwork.framework */; };
+		D943F3EF2892F89B008C0C8B /* NSELogger.swift in Sources */ = {isa = PBXBuildFile; fileRef = D943F3EE2892F89B008C0C8B /* NSELogger.swift */; };
 		D9AB38D0283C38B10003C038 /* InteractionFinderPerformanceTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = D9AB38CE283C38640003C038 /* InteractionFinderPerformanceTests.swift */; };
 		E1368CBE18A1C36B00109378 /* MessageUI.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = B9EB5ABC1884C002007CBB57 /* MessageUI.framework */; };
 		E44AD4E624E98F440035D7B8 /* PhotoCaptureDismiss.swift in Sources */ = {isa = PBXBuildFile; fileRef = E44AD4E524E98F430035D7B8 /* PhotoCaptureDismiss.swift */; };
@@ -2530,6 +2531,7 @@
 		D2AEACDB16C426DA00C364C0 /* CFNetwork.framework */ = {isa = PBXFileReference; lastKnownFileType = wrapper.framework; name = CFNetwork.framework; path = System/Library/Frameworks/CFNetwork.framework; sourceTree = SDKROOT; };
 		D2F64CFA3B9F3C7EA87B1C37 /* Pods-SignalUI.profiling.xcconfig */ = {isa = PBXFileReference; includeInIndex = 1; lastKnownFileType = text.xcconfig; name = "Pods-SignalUI.profiling.xcconfig"; path = "Pods/Target Support Files/Pods-SignalUI/Pods-SignalUI.profiling.xcconfig"; sourceTree = "<group>"; };
 		D4164D79E1C97918C458A743 /* Pods-SignalShareExtension.testable release.xcconfig */ = {isa = PBXFileReference; includeInIndex = 1; lastKnownFileType = text.xcconfig; name = "Pods-SignalShareExtension.testable release.xcconfig"; path = "Pods/Target Support Files/Pods-SignalShareExtension/Pods-SignalShareExtension.testable release.xcconfig"; sourceTree = "<group>"; };
+		D943F3EE2892F89B008C0C8B /* NSELogger.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = NSELogger.swift; sourceTree = "<group>"; };
 		D9AB38CE283C38640003C038 /* InteractionFinderPerformanceTests.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = InteractionFinderPerformanceTests.swift; sourceTree = "<group>"; };
 		DDBCB034D1DFAF85ADFD5E76 /* Pods-SignalUITests.debug.xcconfig */ = {isa = PBXFileReference; includeInIndex = 1; lastKnownFileType = text.xcconfig; name = "Pods-SignalUITests.debug.xcconfig"; path = "Pods/Target Support Files/Pods-SignalUITests/Pods-SignalUITests.debug.xcconfig"; sourceTree = "<group>"; };
 		DE2DD605305BC6EFAD731723 /* Pods-Signal.debug.xcconfig */ = {isa = PBXFileReference; includeInIndex = 1; lastKnownFileType = text.xcconfig; name = "Pods-Signal.debug.xcconfig"; path = "Pods/Target Support Files/Pods-Signal/Pods-Signal.debug.xcconfig"; sourceTree = "<group>"; };
@@ -2904,6 +2906,7 @@
 				342FFE96272458A7000AC89F /* NSECallMessageHandler.swift */,
 				342FFE97272458AA000AC89F /* NSEContext.swift */,
 				342FFE95272458A4000AC89F /* NSEEnvironment.swift */,
+				D943F3EE2892F89B008C0C8B /* NSELogger.swift */,
 				342FFE9C272458D4000AC89F /* SignalNSE-AppStore.entitlements */,
 				342FFE9B272458D4000AC89F /* SignalNSE.entitlements */,
 			);
@@ -6081,6 +6084,7 @@
 				342FFE99272458AB000AC89F /* NSECallMessageHandler.swift in Sources */,
 				342FFE98272458AB000AC89F /* NSEEnvironment.swift in Sources */,
 				342FFE9A272458AB000AC89F /* NSEContext.swift in Sources */,
+				D943F3EF2892F89B008C0C8B /* NSELogger.swift in Sources */,
 				342FFE8B27245850000AC89F /* NotificationService.swift in Sources */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;

+ 7 - 5
SignalNSE/NSECallMessageHandler.swift

@@ -29,7 +29,9 @@ public class NSECallMessageHandler: NSObject, OWSCallMessageHandler {
         let serverReceivedTimestamp = envelope.serverTimestamp > 0 ? envelope.serverTimestamp : envelope.timestamp
         let approxMessageAge = (serverDeliveryTimestamp - serverReceivedTimestamp)
         guard approxMessageAge < 5 * kMinuteInMs else {
-            Logger.info("Discarding very old call message \(envelope.timestamp). No longer relevant. Sever delivery: \(serverDeliveryTimestamp). Server received: \(serverReceivedTimestamp)")
+            NSELogger.uncorrelated.info(
+                "Discarding very old call message \(envelope.timestamp). No longer relevant. Server delivery: \(serverDeliveryTimestamp). Server received: \(serverReceivedTimestamp)"
+            )
             return .ignore
         }
 
@@ -39,7 +41,7 @@ public class NSECallMessageHandler: NSObject, OWSCallMessageHandler {
         } else if let opaqueMessage = callMessage.opaque, opaqueMessage.urgency == .handleImmediately, FeatureFlags.groupRings {
             return .handoff
         } else {
-            Logger.info("Ignoring call message. Not an offer or urgent opaque message.")
+            NSELogger.uncorrelated.info("Ignoring call message. Not an offer or urgent opaque message.")
             return .ignore
         }
     }
@@ -67,12 +69,12 @@ public class NSECallMessageHandler: NSObject, OWSCallMessageHandler {
                 suspension.invalidate()
             }
 
-            Logger.info("Notifying primary app of incoming call with push payload: \(payload)")
+            NSELogger.uncorrelated.info("Notifying primary app of incoming call with push payload: \(payload)")
             CXProvider.reportNewIncomingVoIPPushPayload(payload.payloadDict) { error in
                 if let error = error {
                     owsFailDebug("Failed to notify main app of call message: \(error)")
                 } else {
-                    Logger.info("Successfully notified main app of call message.")
+                    NSELogger.uncorrelated.info("Successfully notified main app of call message.")
                 }
             }
         } catch {
@@ -126,7 +128,7 @@ public class NSECallMessageHandler: NSObject, OWSCallMessageHandler {
         serverReceivedTimestamp: UInt64,
         completion: @escaping () -> Void
     ) {
-        Logger.info("Received group call update for thread \(groupThread.uniqueId)")
+        NSELogger.uncorrelated.info("Received group call update for thread \(groupThread.uniqueId)")
         lightweightCallManager?.peekCallAndUpdateThread(
             groupThread,
             expectedEraId: updateMessage.eraID,

+ 8 - 6
SignalNSE/NSEContext.swift

@@ -23,7 +23,7 @@ class NSEContext: NSObject, AppContext {
     let appLaunchTime = Date()
     lazy var buildTime: Date = {
         guard let buildTimestamp = Bundle.main.object(forInfoDictionaryKey: "BuildTimestamp") as? TimeInterval, buildTimestamp > 0 else {
-            Logger.debug("No build timestamp, assuming app never expires.")
+            NSELogger.uncorrelated.debug("No build timestamp, assuming app never expires.")
             return .distantFuture
         }
 
@@ -64,17 +64,19 @@ class NSEContext: NSObject, AppContext {
         queue: .global()
     )
 
-    override init() {
+    init(logger: NSELogger) {
         super.init()
 
+        logger.info("NSEContext init()")
+
         memoryPressureSource.setEventHandler { [weak self] in
             if let self = self {
-                Logger.warn("Memory pressure event: \(self.memoryPressureSource.memoryEventDescription)")
+                logger.warn("Memory pressure event: \(self.memoryPressureSource.memoryEventDescription)")
             } else {
-                Logger.warn("Memory pressure event.")
+                logger.warn("Memory pressure event.")
             }
-            Logger.warn("Current memory usage: \(LocalDevice.memoryUsageString)")
-            Logger.flush()
+            logger.warn("Current memory usage: \(LocalDevice.memoryUsageString)")
+            logger.flush()
         }
         memoryPressureSource.resume()
 

+ 27 - 25
SignalNSE/NSEEnvironment.swift

@@ -16,7 +16,10 @@ class NSEEnvironment: Dependencies {
 
     private static var mainAppDarwinQueue: DispatchQueue { .global(qos: .userInitiated) }
 
-    func askMainAppToHandleReceipt(handledCallback: @escaping (_ mainAppHandledReceipt: Bool) -> Void) {
+    func askMainAppToHandleReceipt(
+        logger: NSELogger,
+        handledCallback: @escaping (_ mainAppHandledReceipt: Bool) -> Void
+    ) {
         Self.mainAppDarwinQueue.async {
             // We track whether we've ever handled the call back to ensure
             // we only notify the caller once and avoid any races that may
@@ -25,7 +28,7 @@ class NSEEnvironment: Dependencies {
             let hasCalledBack = AtomicBool(false)
 
             if DebugFlags.internalLogging {
-                Logger.info("Requesting main app to handle incoming message.")
+                logger.info("Requesting main app to handle incoming message.")
             }
 
             // Listen for an indication that the main app is going to handle
@@ -39,7 +42,7 @@ class NSEEnvironment: Dependencies {
                 }
 
                 if DebugFlags.internalLogging {
-                    Logger.info("Main app ack'd.")
+                    logger.info("Main app ack'd.")
                 }
 
                 handledCallback(true)
@@ -60,7 +63,7 @@ class NSEEnvironment: Dependencies {
                 }
 
                 if DebugFlags.internalLogging {
-                    Logger.info("Did timeout.")
+                    logger.info("Did timeout.")
                 }
 
                 // If we haven't called back yet and removed the observer token,
@@ -72,7 +75,7 @@ class NSEEnvironment: Dependencies {
     }
 
     private var mainAppLaunchObserverToken = DarwinNotificationInvalidObserver
-    func listenForMainAppLaunch() {
+    func listenForMainAppLaunch(logger: NSELogger) {
         guard !DarwinNotificationCenter.isValidObserver(mainAppLaunchObserverToken) else { return }
         mainAppLaunchObserverToken = DarwinNotificationCenter.addObserver(for: .mainAppLaunched, queue: .global(), using: { _ in
             // If we're currently processing messages we want to commit
@@ -83,10 +86,10 @@ class NSEEnvironment: Dependencies {
             // ourselves as a last resort.
             // TODO: We could eventually make the message fetch process
             // cancellable to never have to exit here.
-            Logger.warn("Main app launched.")
+            logger.warn("Main app launched.")
             guard self.isProcessingMessages else { return }
-            Logger.warn("Exiting because main app launched while we were processing messages.")
-            Logger.flush()
+            logger.warn("Exiting because main app launched while we were processing messages.")
+            logger.flush()
             exit(0)
         })
     }
@@ -100,43 +103,43 @@ class NSEEnvironment: Dependencies {
     }
 
     // This should be the first thing we do.
-    public func ensureAppContext() {
+    public func ensureAppContext(logger: NSELogger) {
         unfairLock.withLock {
             if _hasAppContext {
                 return
             }
             // This should be the first thing we do.
-            SetCurrentAppContext(NSEContext())
+            SetCurrentAppContext(NSEContext(logger: logger))
             _hasAppContext = true
         }
     }
 
     private var isSetup = AtomicBool(false)
 
-    func setupIfNecessary() -> UNNotificationContent? {
+    func setupIfNecessary(logger: NSELogger) -> UNNotificationContent? {
         guard isSetup.tryToSetFlag() else { return nil }
-        return DispatchQueue.main.sync { setup() }
+        return DispatchQueue.main.sync { setup(logger: logger) }
     }
 
     private var areVersionMigrationsComplete = false
-    private func setup() -> UNNotificationContent? {
+    private func setup(logger: NSELogger) -> UNNotificationContent? {
         AssertIsOnMainThread()
 
         // This should be the first thing we do.
-        ensureAppContext()
+        ensureAppContext(logger: logger)
 
         DebugLogger.shared().enableTTYLogging()
         if OWSPreferences.isLoggingEnabled() || _isDebugAssertConfiguration() {
             DebugLogger.shared().enableFileLogging()
         }
 
-        Logger.info("")
+        logger.info("")
 
         _ = AppVersion.shared()
 
         Cryptography.seedRandom()
 
-        if let errorContent = Self.verifyDBKeysAvailable() {
+        if let errorContent = Self.verifyDBKeysAvailable(logger: logger) {
             return errorContent
         }
 
@@ -155,7 +158,7 @@ class NSEEnvironment: Dependencies {
                     owsFailDebug("Error \(error)")
                     return
                 }
-                self?.versionMigrationsDidComplete()
+                self?.versionMigrationsDidComplete(logger: logger)
             }
         )
 
@@ -166,19 +169,19 @@ class NSEEnvironment: Dependencies {
             object: nil
         )
 
-        Logger.info("completed.")
+        logger.info("completed.")
 
         OWSAnalytics.appLaunchDidBegin()
 
-        listenForMainAppLaunch()
+        listenForMainAppLaunch(logger: logger)
 
         return nil
     }
 
-    public static func verifyDBKeysAvailable() -> UNNotificationContent? {
+    public static func verifyDBKeysAvailable(logger: NSELogger) -> UNNotificationContent? {
         guard !StorageCoordinator.hasGrdbFile || !GRDBDatabaseStorageAdapter.isKeyAccessible else { return nil }
 
-        Logger.info("Database password is not accessible, posting generic notification.")
+        logger.info("Database password is not accessible, posting generic notification.")
 
         let content = UNMutableNotificationContent()
         let notificationFormat = OWSLocalizedString(
@@ -189,11 +192,10 @@ class NSEEnvironment: Dependencies {
         return content
     }
 
-    @objc
-    private func versionMigrationsDidComplete() {
+    private func versionMigrationsDidComplete(logger: NSELogger) {
         AssertIsOnMainThread()
 
-        Logger.debug("")
+        logger.debug("")
 
         areVersionMigrationsComplete = true
 
@@ -204,7 +206,7 @@ class NSEEnvironment: Dependencies {
     private func storageIsReady() {
         AssertIsOnMainThread()
 
-        Logger.debug("")
+        NSELogger.uncorrelated.debug("")
 
         checkIsAppReady()
     }

+ 76 - 0
SignalNSE/NSELogger.swift

@@ -0,0 +1,76 @@
+//
+//  Copyright (c) 2022 Open Whisper Systems. All rights reserved.
+//
+
+import Foundation
+import SignalCoreKit
+
+class NSELogger {
+    static let uncorrelated = NSELogger(withCustomId: "uncorrelated")
+
+    let correlationId: String
+
+    init() {
+        self.correlationId = UUID().uuidString
+    }
+
+    private init(withCustomId customId: String) {
+        self.correlationId = customId
+    }
+
+    func debug(
+        _ logString: @autoclosure () -> String,
+        file: String = #file,
+        function: String = #function,
+        line: Int = #line
+    ) {
+        Logger.debug(
+            makeLogString(logString()),
+            file: file, function: function, line: line
+        )
+    }
+
+    func info(
+        _ logString: @autoclosure () -> String,
+        file: String = #file,
+        function: String = #function,
+        line: Int = #line
+    ) {
+        Logger.info(
+            makeLogString(logString()),
+            file: file, function: function, line: line
+        )
+    }
+
+    func warn(
+        _ logString: @autoclosure () -> String,
+        file: String = #file,
+        function: String = #function,
+        line: Int = #line
+    ) {
+        Logger.warn(
+            makeLogString(logString()),
+            file: file, function: function, line: line
+        )
+    }
+
+    func error(
+        _ logString: @autoclosure () -> String,
+        file: String = #file,
+        function: String = #function,
+        line: Int = #line
+    ) {
+        Logger.error(
+            makeLogString(logString()),
+            file: file, function: function, line: line
+        )
+    }
+
+    func flush() {
+        Logger.flush()
+    }
+
+    private func makeLogString(_ logString: @autoclosure () -> String) -> String {
+        "\(logString()) {\(correlationId)}"
+    }
+}

+ 37 - 31
SignalNSE/NotificationService.swift

@@ -47,7 +47,7 @@ class NotificationService: UNNotificationServiceExtension {
             if DebugFlags.internalLogging,
                _logTimer == nil {
                 _logTimer = OffMainThreadTimer(timeInterval: 1.0, repeats: true) { _ in
-                    Logger.info("... memoryUsage: \(LocalDevice.memoryUsageString)")
+                    NSELogger.uncorrelated.info("... memoryUsage: \(LocalDevice.memoryUsageString)")
                 }
             }
 
@@ -71,15 +71,15 @@ class NotificationService: UNNotificationServiceExtension {
     // MARK: -
 
     // This method is thread-safe.
-    func completeSilenty(timeHasExpired: Bool = false) {
+    func completeSilently(timeHasExpired: Bool = false, logger: NSELogger) {
 
         let nseCount = Self.nseDidComplete()
 
         guard let contentHandler = contentHandler.swap(nil) else {
             if DebugFlags.internalLogging {
-                Logger.warn("No contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
+                logger.warn("No contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
             }
-            Logger.flush()
+            logger.flush()
             return
         }
 
@@ -105,42 +105,46 @@ class NotificationService: UNNotificationServiceExtension {
         content.badge = updatedBadgeCount
 
         if DebugFlags.internalLogging {
-            Logger.info("Invoking contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
+            logger.info("Invoking contentHandler, memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount).")
         }
-        Logger.flush()
+        logger.flush()
 
         contentHandler(content)
     }
 
-    override func didReceive(_ request: UNNotificationRequest, withContentHandler contentHandler: @escaping (UNNotificationContent) -> Void) {
+    override func didReceive(
+        _ request: UNNotificationRequest,
+        withContentHandler contentHandler: @escaping (UNNotificationContent) -> Void
+    ) {
+        let logger = NSELogger()
 
         // This should be the first thing we do.
-        environment.ensureAppContext()
+        environment.ensureAppContext(logger: logger)
 
         // Detect and handle "no GRDB file" and "no keychain access; device
         // not yet unlocked for first time" cases _before_ calling
         // setupIfNecessary().
-        if let errorContent = NSEEnvironment.verifyDBKeysAvailable() {
+        if let errorContent = NSEEnvironment.verifyDBKeysAvailable(logger: logger) {
             if hasShownFirstUnlockError.tryToSetFlag() {
-                NSLog("DB Keys not accessible; showing error.")
+                logger.error("DB Keys not accessible; showing error.")
                 contentHandler(errorContent)
             } else {
                 // Only show a single error if we receive multiple pushes
                 // before first device unlock.
-                NSLog("DB Keys not accessible; completing silently.")
+                logger.error("DB Keys not accessible; completing silently.")
                 let emptyContent = UNMutableNotificationContent()
                 contentHandler(emptyContent)
             }
             return
         }
 
-        if let errorContent = environment.setupIfNecessary() {
+        if let errorContent = environment.setupIfNecessary(logger: logger) {
             // This should not occur; see above.  If we've reached this
             // point, the NSEEnvironment.isSetup flag is already set,
             // but the environment has _not_ been setup successfully.
             // We need to terminate the NSE to return to a good state.
-            Logger.warn("Posting error notification and skipping processing.")
-            Logger.flush()
+            logger.warn("Posting error notification and skipping processing.")
+            logger.flush()
             contentHandler(errorContent)
             fatalError("Posting error notification and skipping processing.")
         }
@@ -151,19 +155,21 @@ class NotificationService: UNNotificationServiceExtension {
 
         let nseCount = Self.nseDidStart()
 
-        Logger.info("Received notification in class: \(self), thread: \(Thread.current), pid: \(ProcessInfo.processInfo.processIdentifier), memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount)")
+        logger.info(
+            "Received notification in class: \(self), thread: \(Thread.current), pid: \(ProcessInfo.processInfo.processIdentifier), memoryUsage: \(LocalDevice.memoryUsageString), nseCount: \(nseCount)"
+        )
 
         AppReadiness.runNowOrWhenAppDidBecomeReadySync {
-            environment.askMainAppToHandleReceipt { [weak self] mainAppHandledReceipt in
+            environment.askMainAppToHandleReceipt(logger: logger) { [weak self] mainAppHandledReceipt in
                 guard !mainAppHandledReceipt else {
-                    Logger.info("Received notification handled by main application, memoryUsage: \(LocalDevice.memoryUsageString).")
-                    self?.completeSilenty()
+                    logger.info("Received notification handled by main application, memoryUsage: \(LocalDevice.memoryUsageString).")
+                    self?.completeSilently(logger: logger)
                     return
                 }
 
-                Logger.info("Processing received notification, memoryUsage: \(LocalDevice.memoryUsageString).")
+                logger.info("Processing received notification, memoryUsage: \(LocalDevice.memoryUsageString).")
 
-                self?.fetchAndProcessMessages()
+                self?.fetchAndProcessMessages(logger: logger)
             }
         }
     }
@@ -175,19 +181,19 @@ class NotificationService: UNNotificationServiceExtension {
         // We complete silently here so that nothing is presented to the user.
         // By default the OS will present whatever the raw content of the original
         // notification is to the user otherwise.
-        completeSilenty(timeHasExpired: true)
+        completeSilently(timeHasExpired: true, logger: .uncorrelated)
     }
 
     // This method is thread-safe.
-    private func fetchAndProcessMessages() {
+    private func fetchAndProcessMessages(logger: NSELogger) {
         guard !AppExpiry.shared.isExpired else {
             owsFailDebug("Not processing notifications for expired application.")
-            return completeSilenty()
+            return completeSilently(logger: logger)
         }
 
         environment.processingMessageCounter.increment()
 
-        Logger.info("Beginning message fetch.")
+        logger.info("Beginning message fetch.")
 
         let fetchPromise = messageFetcherJob.run().promise
         fetchPromise.timeout(seconds: 20, description: "Message Fetch Timeout.") {
@@ -196,7 +202,7 @@ class NotificationService: UNNotificationServiceExtension {
             // Do nothing, Promise.timeout() will log timeouts.
         }
         fetchPromise.then(on: .global()) { [weak self] () -> Promise<Void> in
-            Logger.info("Waiting for processing to complete.")
+            logger.info("Waiting for processing to complete.")
             guard let self = self else { return Promise.value(()) }
 
             let runningAndCompletedPromises = AtomicArray<(String, Promise<Void>)>()
@@ -206,7 +212,7 @@ class NotificationService: UNNotificationServiceExtension {
                 runningAndCompletedPromises.append(("MessageProcessorCompletion", promise))
                 return promise
             }.then(on: .global()) { () -> Promise<Void> in
-                Logger.info("Initial message processing complete.")
+                logger.info("Initial message processing complete.")
                 // Wait until all async side effects of message processing are complete.
                 let completionPromises: [(String, Promise<Void>)] = [
                     // Wait until all ACKs are complete.
@@ -220,7 +226,7 @@ class NotificationService: UNNotificationServiceExtension {
                 ]
                 let joinedPromise = Promise.when(resolved: completionPromises.map { (name, promise) in
                     promise.done(on: .global()) {
-                        Logger.info("\(name) complete")
+                        logger.info("\(name) complete")
                     }
                 })
                 completionPromises.forEach { runningAndCompletedPromises.append($0) }
@@ -233,7 +239,7 @@ class NotificationService: UNNotificationServiceExtension {
             }
             processingCompletePromise.timeout(seconds: 20, ticksWhileSuspended: true, description: "Message Processing Timeout.") {
                 runningAndCompletedPromises.get().filter { $0.1.isSealed == false }.forEach {
-                    Logger.warn("Completion promise: \($0.0) did not finish.")
+                    logger.warn("Completion promise: \($0.0) did not finish.")
                 }
                 return NotificationServiceError.timeout
             }.catch { _ in
@@ -241,11 +247,11 @@ class NotificationService: UNNotificationServiceExtension {
             }
             return processingCompletePromise
         }.ensure(on: .global()) { [weak self] in
-            Logger.info("Message fetch completed.")
+            logger.info("Message fetch completed.")
             environment.processingMessageCounter.decrementOrZero()
-            self?.completeSilenty()
+            self?.completeSilently(logger: logger)
         }.catch(on: .global()) { error in
-            Logger.warn("Error: \(error)")
+            logger.error("Error: \(error)")
         }
     }