From 07712f69778fbeefeaa0d4f48b308bc2e83ed73a Mon Sep 17 00:00:00 2001 From: Jordan Rose Date: Tue, 1 Mar 2022 15:35:57 -0800 Subject: [PATCH 1/4] NSE: Log when each step of message processing is complete Previously we only logged when everything was complete, or if we timed out, but neither helps when tracking down memory overallocation issues, since the NSE is killed before any of these logs print. With this we have a better chance at seeing which jobs are outstanding. --- SignalNSE/NotificationService.swift | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/SignalNSE/NotificationService.swift b/SignalNSE/NotificationService.swift index 14bd3a76fb..1554493d4b 100644 --- a/SignalNSE/NotificationService.swift +++ b/SignalNSE/NotificationService.swift @@ -206,6 +206,7 @@ class NotificationService: UNNotificationServiceExtension { runningAndCompletedPromises.append(("MessageProcessorCompletion", promise)) return promise }.then(on: .global()) { () -> Promise in + Logger.info("Initial message processing complete.") // Wait until all async side effects of // message processing are complete. let completionPromises: [(String, Promise)] = [ @@ -220,7 +221,11 @@ class NotificationService: UNNotificationServiceExtension { // Wait until all sync requests are fulfilled. ("Pending sync request", OWSMessageManager.pendingTasksPromise()) ] - let joinedPromise = Promise.when(resolved: completionPromises.map { $0.1 }) + let joinedPromise = Promise.when(resolved: completionPromises.map { (name, promise) in + promise.done(on: .global()) { + Logger.info("\(name) complete") + } + }) completionPromises.forEach { runningAndCompletedPromises.append($0) } return joinedPromise.asVoid() } From 0c04b3e575e24ad0dfe1334215ee808d3fd43cfe Mon Sep 17 00:00:00 2001 From: Jordan Rose Date: Tue, 1 Mar 2022 15:52:21 -0800 Subject: [PATCH 2/4] Log on network requests with large content lengths This is intended to catch requests to the server that could be causing problems in the memory-constrained environment of the NSE. It's unlikely, since we log *all* network requests and we haven't seen any suspicious ones, but it could still be useful in the future. Note that this only applies to data tasks, not download tasks; a download task can be as big as it needs to be. --- SignalServiceKit/src/Network/OWSURLSession.swift | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/SignalServiceKit/src/Network/OWSURLSession.swift b/SignalServiceKit/src/Network/OWSURLSession.swift index b417b16be9..cf5f174dba 100644 --- a/SignalServiceKit/src/Network/OWSURLSession.swift +++ b/SignalServiceKit/src/Network/OWSURLSession.swift @@ -806,6 +806,11 @@ extension OWSURLSession: URLSessionDownloadDelegate { completionHandler(.cancel) return } + if response.expectedContentLength > 800_000 { + let formattedContentLength = OWSFormat.formatFileSize(UInt(response.expectedContentLength)) + let urlString = response.url.map { String(describing: $0) } ?? "" + Logger.warn("Large response (\(formattedContentLength)) for \(urlString)") + } completionHandler(.allow) } From 34d60bf833a716df3925068354dcb2fb6542e888 Mon Sep 17 00:00:00 2001 From: Jordan Rose Date: Tue, 1 Mar 2022 16:13:30 -0800 Subject: [PATCH 3/4] Always log when we present a user notification for an incoming message --- .../Notifications/UserNotificationsAdaptee.swift | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/SignalMessaging/Notifications/UserNotificationsAdaptee.swift b/SignalMessaging/Notifications/UserNotificationsAdaptee.swift index d6bb15023f..51e70325e1 100644 --- a/SignalMessaging/Notifications/UserNotificationsAdaptee.swift +++ b/SignalMessaging/Notifications/UserNotificationsAdaptee.swift @@ -1,5 +1,5 @@ // -// Copyright (c) 2021 Open Whisper Systems. All rights reserved. +// Copyright (c) 2022 Open Whisper Systems. All rights reserved. // import Foundation @@ -250,9 +250,7 @@ class UserNotificationPresenterAdaptee: NSObject, NotificationPresenterAdaptee { let request = UNNotificationRequest(identifier: notificationIdentifier, content: contentToUse, trigger: trigger) - if DebugFlags.internalLogging { - Logger.info("presenting notification with identifier: \(notificationIdentifier)") - } + Logger.info("presenting notification with identifier: \(notificationIdentifier)") notificationCenter.add(request) { (error: Error?) in if let error = error { owsFailDebug("Error: \(error)") From acba11b9664442cdba71be767b20b95ac33a034a Mon Sep 17 00:00:00 2001 From: Jordan Rose Date: Tue, 1 Mar 2022 16:13:51 -0800 Subject: [PATCH 4/4] Turn on OWSLogger's aggressive flushing in the NSE for everyone And do it sooner: at 5MB remaining instead of 1MB. This matches the inverted condition of 20MB used, as well as where we're seeing sudden spikes and then nothing in our logs. --- SignalServiceKit/src/Util/LocalDevice.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/SignalServiceKit/src/Util/LocalDevice.swift b/SignalServiceKit/src/Util/LocalDevice.swift index fc5900359a..4b49635654 100644 --- a/SignalServiceKit/src/Util/LocalDevice.swift +++ b/SignalServiceKit/src/Util/LocalDevice.swift @@ -60,12 +60,12 @@ public class LocalDevice: NSObject { mallocAllocations: Int64(statistics.size_allocated) ) - if DebugFlags.internalLogging, CurrentAppContext().isNSE { + if CurrentAppContext().isNSE { if result.bytesRemaining > 0 { // If we're running out of free memory, let's start aggressively flushing // our log messages. This way, we don't lose any logs when we're suddenly terminated. // There's a perf cost here, but we're going to be killed soon anyway so it's not a big deal. - OWSLogger.aggressiveFlushing = result.bytesRemaining < (1024 * 1024) + OWSLogger.aggressiveFlushing = result.bytesRemaining < (4 * 1024 * 1024) } else { // The source of the remaining bits is fairly under documented. In my testing, things // seem to be working as expected. Just to be safe, let's interpret 0 free bytes as invalid