chore: log sync phases in legacy code and new code - WPB-15289

WireDomain/Sources/WireDomain/Synchronization/SyncManager.swift

@@ -45,6 +45,26 @@ final class SyncManager: SyncManagerProtocol {
         case failedToPerformSlowSync(Error)
     }
 
+    // MARK: - Logs
+
+    private enum SyncPhaseName: String {
+        case pullingLastUpdateEventID
+        case pullingSelfTeam
+        case pullingSelfTeamRoles
+        case pullingSelfTeamMembers
+        case pullingConnections
+        case pullingKnownUsers
+        case pullingConversations
+        case pullingSelfUser
+        case pullingSelfLegalholdInfo
+        case pullingConversationLabels
+        case pullingFeatureConfigs
+        case pullingMLSBackendStatus
+        case pushingSupportedProtocols
+        case resolvingOneOnOneConversations
+        case pullPendingEvents // quick sync
+    }
+
     // MARK: - Properties
 
     private(set) var syncState: SyncState = .suspended
@@ -63,6 +83,7 @@ final class SyncManager: SyncManagerProtocol {
     private let pushSupportedProtocolsUseCase: any PushSupportedProtocolsUseCaseProtocol
     private let mlsProvider: MLSProvider
     private let context: NSManagedObjectContext
+    private let syncTimeTracker = SyncTimeTracker()
 
     // MARK: - Update event processor
 
@@ -100,21 +121,65 @@ final class SyncManager: SyncManagerProtocol {
 
     func performSlowSync() async throws {
         do {
+            syncTimeTracker.reset()
+
+            logSyncPhaseStarted(for: .pullingLastUpdateEventID)
             try await updateEventsRepository.pullLastEventID()
+            logSyncPhaseCompleted(for: .pullingLastUpdateEventID)
+
+            logSyncPhaseStarted(for: .pullingSelfTeam)
             try await teamRepository.pullSelfTeam()
+            logSyncPhaseCompleted(for: .pullingSelfTeam)
+
+            logSyncPhaseStarted(for: .pullingSelfTeamRoles)
             try await teamRepository.pullSelfTeamRoles()
+            logSyncPhaseCompleted(for: .pullingSelfTeamRoles)
+
+            logSyncPhaseStarted(for: .pullingSelfTeamMembers)
             try await teamRepository.pullSelfTeamMembers()
+            logSyncPhaseCompleted(for: .pullingSelfTeamMembers)
+
+            logSyncPhaseStarted(for: .pullingConnections)
             try await connectionsRepository.pullConnections()
+            logSyncPhaseCompleted(for: .pullingConnections)
+
+            logSyncPhaseStarted(for: .pullingConversations)
             try await conversationsRepository.pullConversations()
+            logSyncPhaseCompleted(for: .pullingConversations)
+
+            logSyncPhaseStarted(for: .pullingKnownUsers)
             try await userRepository.pullKnownUsers()
+            logSyncPhaseCompleted(for: .pullingKnownUsers)
+
+            logSyncPhaseStarted(for: .pullingSelfUser)
             try await userRepository.pullSelfUser()
+            logSyncPhaseCompleted(for: .pullingSelfUser)
+
+            logSyncPhaseStarted(for: .pullingSelfLegalholdInfo)
             try await teamRepository.pullSelfLegalholdInfo()
+            logSyncPhaseCompleted(for: .pullingSelfLegalholdInfo)
+
+            logSyncPhaseStarted(for: .pullingConversationLabels)
             try await conversationLabelsRepository.pullConversationLabels()
+            logSyncPhaseCompleted(for: .pullingConversationLabels)
+
+            logSyncPhaseStarted(for: .pullingFeatureConfigs)
             try await featureConfigsRepository.pullFeatureConfigs()
+            logSyncPhaseCompleted(for: .pullingFeatureConfigs)
+
+            logSyncPhaseStarted(for: .pullingMLSBackendStatus)
             await backendConfigRepository.pullMLSBackendStatus()
+            logSyncPhaseCompleted(for: .pullingMLSBackendStatus)
+
+            logSyncPhaseStarted(for: .pushingSupportedProtocols)
             try await pushSupportedProtocolsUseCase.invoke()
+            logSyncPhaseCompleted(for: .pushingSupportedProtocols)
+
+            logSyncPhaseStarted(for: .resolvingOneOnOneConversations)
             let oneOnOneResolver = makeOneOnOneResolver()
             try await oneOnOneResolver.resolveAllOneOnOneConversations()
+            logSyncPhaseCompleted(for: .resolvingOneOnOneConversations, completedAllPhases: true)
+
         } catch {
             throw Failure.failedToPerformSlowSync(error)
         }
@@ -146,7 +211,18 @@ final class SyncManager: SyncManagerProtocol {
 
         do {
             syncState = .quickSync(quickSyncTask)
+
+            syncTimeTracker.reset()
+
+            logSyncPhaseStarted(for: .pullPendingEvents)
+
             try await quickSyncTask.value
+
+            logSyncPhaseCompleted(
+                for: .pullPendingEvents,
+                completedAllPhases: true
+            )
+
         } catch {
             try await suspend()
             throw error
@@ -250,4 +326,54 @@ final class SyncManager: SyncManagerProtocol {
         }
     }
 
+    private func logSyncPhaseStarted(
+        for phase: SyncPhaseName
+    ) {
+        let syncType = phase != .pullPendingEvents ? "slow sync" : "quick sync"
+        let attributes: LogAttributes = [
+            .syncType: syncType,
+            .syncSystem: "new",
+            .syncPhase: phase.rawValue,
+            .public: true
+        ]
+
+        WireLogger.sync.info("Started sync phase", attributes: attributes)
+    }
+
+    private func logSyncPhaseCompleted(
+        for phase: SyncPhaseName,
+        completedAllPhases: Bool = false
+    ) {
+        let syncType = phase != .pullPendingEvents ? "slow sync" : "quick sync"
+        let currentTime = Date.now
+        let duration = currentTime.timeIntervalSince(syncTimeTracker.phaseStartTime)
+        let message = "Completed sync phase"
+        let logAttributes: LogAttributes = [
+            .syncType: syncType,
+            .duration: String(duration),
+            .syncSystem: "new",
+            .syncPhase: phase.rawValue,
+            .public: true
+        ]
+
+        WireLogger.sync.info(message, attributes: logAttributes)
+
+        syncTimeTracker.addPhaseDuration(duration)
+        syncTimeTracker.resetStartTime() // reset for next sync phase
+
+        if completedAllPhases {
+            let message = "Completed \(syncType)"
+            let syncTotalDuration = syncTimeTracker.totalSyncDuration()
+            let logAttributes: LogAttributes = [
+                .syncType: syncType,
+                .syncSystem: "new",
+                .duration: String(syncTotalDuration),
+                .public: true
+            ]
+
+            WireLogger.sync.info(message, attributes: logAttributes)
+            syncTimeTracker.reset() // Sync is completed and logged, resetting tracked time values
+        }
+    }
+
 }

WireDomain/Sources/WireDomain/Synchronization/SyncTimeTracker.swift

@@ -0,0 +1,55 @@
+//
+// Wire
+// Copyright (C) 2025 Wire Swiss GmbH
+//
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see http://www.gnu.org/licenses/.
+//
+
+import Foundation
+import WireLogging
+
+/// Keep tracks of each sync phase duration and the start time of a given phase.
+///
+/// Used to log time for each sync phase along with the time a slow / quick sync took to complete.
+public final class SyncTimeTracker {
+    public var phaseStartTime: Date
+    private var phasesDurations: [TimeInterval]
+
+    public init(
+        phasesDurations: [TimeInterval] = [TimeInterval](),
+        phaseStartTime: Date = .now
+    ) {
+        self.phasesDurations = phasesDurations
+        self.phaseStartTime = phaseStartTime
+    }
+
+    public func addPhaseDuration(
+        _ duration: TimeInterval
+    ) {
+        phasesDurations.append(duration)
+    }
+
+    public func totalSyncDuration() -> TimeInterval {
+        phasesDurations.reduce(0, +)
+    }
+
+    public func resetStartTime() {
+        phaseStartTime = .now
+    }
+
+    public func reset() {
+        phaseStartTime = .now
+        phasesDurations = []
+    }
+}

WireLogging/Sources/WireLogging/LogAttributes.swift

@@ -37,6 +37,9 @@ public enum LogAttributesKey: String, Comparable, Sendable {
     case processId = "process_id"
     case processName = "process_name"
     case coreCryptoContext = "core_crypto_context"
+    case duration
+    case syncType = "sync_type"
+    case syncSystem = "sync_system"
 
     public static func < (lhs: LogAttributesKey, rhs: LogAttributesKey) -> Bool {
         lhs.rawValue < rhs.rawValue

wire-ios-request-strategy/Sources/Synchronization/SyncPhase.swift

@@ -41,11 +41,16 @@ public enum SyncPhase: Int, CustomStringConvertible, CaseIterable {
     case done
 
     static let lastSlowSyncPhase: SyncPhase = .evaluate1on1ConversationsForMLS
+    static let lastQuickSyncPhase: SyncPhase = .fetchingMissedEvents
 
     public var isLastSlowSyncPhase: Bool {
         self == Self.lastSlowSyncPhase
     }
 
+    public var isLastQuickSyncPhase: Bool {
+        self == Self.lastQuickSyncPhase
+    }
+
     public var isSyncing: Bool {
         self != .done
     }

wire-ios-sync-engine/Source/Synchronization/Strategies/SelfSupportedProtocolsRequestStrategy.swift

@@ -62,8 +62,6 @@ public final class SelfSupportedProtocolsRequestStrategy: AbstractRequestStrateg
             return nil
         }
 
-        WireLogger.sync.info("start slow sync phase: \(syncPhase.description)")
-
         requestSync.readyForNextRequestIfNotBusy()
         return requestSync.nextRequest(for: apiVersion)
     }

wire-ios-sync-engine/Source/Synchronization/Transcoders/ZMLastUpdateEventIDTranscoder.m

@@ -84,6 +84,7 @@ - (SyncPhase)isSyncing
 - (ZMTransportRequest *)nextRequestIfAllowedForAPIVersion:(APIVersion)apiVersion
 {
     if (self.isSyncing && !self.isDownloadingLastUpdateEventID) {
+        [self.syncStatus resetSyncTimeTracker]; // Slow sync started, resetting tracked time values
         [self startRequestingLastUpdateEventIDWithoutPersistingIt];
         return [self.requestGenerators nextRequestForAPIVersion:apiVersion];
     }