chore: add logging to help investigate hang - WPB-22986 🍒 (#4281)

Co-authored-by: Sam Wyndham <samwyndham@users.noreply.github.com>

Author: github-actions[bot]

WireLogging/Sources/WireLogging/LogAttributes.swift

@@ -48,6 +48,7 @@ public enum LogAttributesKey: String, Comparable, Sendable {
     case syncType = "sync_type"
     case syncVersion = "sync_version"
     case workItemID = "work_item_id"
+    case isNewClient = "is_new_client"
 
     public static func < (lhs: LogAttributesKey, rhs: LogAttributesKey) -> Bool {
         lhs.rawValue < rhs.rawValue

WireLogging/Sources/WireLogging/WireLogger+MessageTime.swift

@@ -25,17 +25,47 @@ public extension WireLogger {
         attributes: LogAttributes = [:],
         block: () async throws -> T
     ) async throws -> T {
+        let context = measureTimeStart(label: label, attributes: attributes)
+        let result = try await block()
+        measureTimeEnd(context: context)
+        return result
+    }
+
+    func measureTime<T, E: Error>(
+        label: String,
+        attributes: LogAttributes = [:],
+        block: () throws(E) -> T
+    ) throws(E) -> T {
+        let context = measureTimeStart(label: label, attributes: attributes)
+        let result = try block()
+        measureTimeEnd(context: context)
+        return result
+    }
+
+    // MARK: - Helpers
+
+    private struct Context {
+        let start: Date
+        let label: String
+        let attributes: LogAttributes
+    }
+
+    private func measureTimeStart(
+        label: String,
+        attributes: LogAttributes
+    ) -> Context {
         let startMessage = "starting \(label)"
         info(startMessage, attributes: attributes)
-        let start = Date.now
-        let result = try await block()
-        let durationInSeconds = start.timeIntervalSinceNow.magnitude
-        var updatedAttributes = attributes
+        return Context(start: Date.now, label: label, attributes: attributes)
+    }
+
+    private func measureTimeEnd(context: Context) {
+        let durationInSeconds = context.start.timeIntervalSinceNow.magnitude
+        var updatedAttributes = context.attributes
         let formattedDuration = String(format: "%.2f", durationInSeconds)
         updatedAttributes[.duration] = formattedDuration
-        let completedMessage = "completed \(label)"
+        let completedMessage = "completed \(context.label)"
         info(completedMessage, attributes: updatedAttributes)
-        return result
     }
 
 }

wire-ios-sync-engine/Source/Synchronization/StrategyDirectory.swift

@@ -310,7 +310,7 @@ public class StrategyDirectory: NSObject, StrategyDirectoryProtocol {
         ]
     }
 
-    func makeClientRelatedStategies(
+    func makeClientRelatedStrategies(
         applicationStatusDirectory: ApplicationStatusDirectory,
         syncContext: NSManagedObjectContext,
         transportSession: TransportSessionType,

wire-ios-sync-engine/Source/UserSession/ZMUserSession/ZMUserSession.swift

@@ -607,12 +607,12 @@ public final class ZMUserSession: NSObject {
 
             // Create and perform sync if there is a self client.
             if let selfClientID = selfUserClient.remoteIdentifier {
-                setUpSyncAgent(clientID: selfClientID)
+                setUpSyncAgent(clientID: selfClientID, isNewClient: false)
             }
         }
     }
 
-    func setUpSyncAgent(clientID: String) {
+    func setUpSyncAgent(clientID: String, isNewClient: Bool) {
         let clientSessionComponent = userSessionComponent.clientSessionComponent(
             clientID: clientID,
             completionHandlers: .init(
@@ -654,15 +654,19 @@ public final class ZMUserSession: NSObject {
                 syncAgent: syncAgent,
                 notificationContext: notificationContext
             )
-            strategyDirectory.makeClientRelatedStategies(
-                applicationStatusDirectory: applicationStatusDirectory,
-                syncContext: syncContext,
-                transportSession: transportSession,
-                pushMessageHandler: localNotificationDispatcher,
-                flowManager: flowManager,
-                incrementalSyncObserver: incrementalSyncObserver,
-                metadata: resolvedBackendMetadata
-            )
+
+            // TODO: [WPB-22986] Remove logging - added this logging temporarily to investigate a hang.
+            WireLogger.session.measureTime(label: "make client strategies", attributes: [.isNewClient: isNewClient]) {
+                strategyDirectory.makeClientRelatedStrategies(
+                    applicationStatusDirectory: applicationStatusDirectory,
+                    syncContext: syncContext,
+                    transportSession: transportSession,
+                    pushMessageHandler: localNotificationDispatcher,
+                    flowManager: flowManager,
+                    incrementalSyncObserver: incrementalSyncObserver,
+                    metadata: resolvedBackendMetadata
+                )
+            }
             syncStrategy?.updateClientContextChangeTrackers()
         }
         Task {
@@ -1384,7 +1388,7 @@ extension ZMUserSession: ZMClientRegistrationStatusDelegate {
         // The client was just registered and still needs to perform the
         // initial sync.
         if let selfClientID = userClient.remoteIdentifier {
-            setUpSyncAgent(clientID: selfClientID)
+            setUpSyncAgent(clientID: selfClientID, isNewClient: true)
             // no migration needed from last sync system as it's a new client
             if userClient.isConsumableNotificationsCapable {
                 // activate new sync with consumable notifications

wire-ios-sync-engine/Tests/Source/UserSession/ZMUserSessionTests.swift

@@ -419,7 +419,7 @@ final class ZMUserSessionTests: ZMUserSessionTestsBase {
             sut.didRegisterSelfUserClient(selfUserClient)
             syncMOC.saveOrRollback()
 
-            sut.setUpSyncAgent(clientID: selfUserClient.remoteIdentifier!)
+            sut.setUpSyncAgent(clientID: selfUserClient.remoteIdentifier!, isNewClient: false)
 
             // WHEN
             sut.didFinishIncrementalSync(isRecovering: false)