Address updater feedback (#3690)

Task/Issue URL:
https://app.asana.com/0/1201048563534612/1209026627874986/f
Tech Design URL:
CC:

**Description**:

Addresses some updater feedback:

- "Install Now" menu item does nothing
- Incorrect Release Notes screen state

Also adds more logging to help track down the edge cases (non-producible
on my machine, but some internal users kept running into them)

**Optional E2E tests**:
- [ ] Run PIR E2E tests
Check this to run the Personal Information Removal end to end tests. If
updating CCF, or any PIR related code, tick this.

**Steps to test this PR**:
1. Download this test build:
https://staticcdn.duckduckgo.com/macos-desktop-browser/a81f9679-e41d-404d-81a6-fd4a461d82f7/testbuilds/5ab32a1/duckduckgo-1.120.0.333.dmg
2. Try different scenarios; use this as reference:
https://app.asana.com/0/1199230911884351/1208882660080993/f
3. Run this Terminal command: `log show --info --predicate 'subsystem ==
"Updates"' --style compact --last 24h > ~/Downloads/updater.log`
4. Give the log file a quick skim; all major update steps should be
there.

<!--
Tagging instructions
If this PR isn't ready to be merged for whatever reason it should be
marked with the `DO NOT MERGE` label (particularly if it's a draft)
If it's pending Product Review/PFR, please add the `Pending Product
Review` label.

If at any point it isn't actively being worked on/ready for
review/otherwise moving forward (besides the above PR/PFR exception)
strongly consider closing it (or not opening it in the first place). If
you decide not to close it, make sure it's labelled to make it clear the
PRs state and comment with more information.
-->

**Definition of Done**:

* [ ] Does this PR satisfy our [Definition of
Done](https://app.asana.com/0/1202500774821704/1207634633537039/f)?

---
###### Internal references:
[Pull Request Review
Checklist](https://app.asana.com/0/1202500774821704/1203764234894239/f)
[Software Engineering
Expectations](https://app.asana.com/0/59792373528535/199064865822552)
[Technical Design
Template](https://app.asana.com/0/59792373528535/184709971311943)
[Pull Request
Documentation](https://app.asana.com/0/1202500774821704/1204012835277482/f)

DuckDuckGo/NavigationBar/View/MoreOptionsMenu.swift

@@ -331,12 +331,20 @@ final class MoreOptionsMenu: NSMenu, NSMenuDelegate {
 #if SPARKLE
         guard NSApp.runType != .uiTests,
               let updateController = Application.appDelegate.updateController,
-              let update = updateController.latestUpdate,
-              !update.isInstalled,
-              updateController.updateProgress.isDone
-        else {
+              let update = updateController.latestUpdate else {
             return
         }
+
+        // Log edge cases where menu item appears but doesn't function
+        // To be removed in a future version
+        if !update.isInstalled, updateController.updateProgress.isDone {
+            updateController.log()
+        }
+
+        guard updateController.hasPendingUpdate else {
+            return
+        }
+
         addItem(UpdateMenuItemFactory.menuItem(for: update))
         addItem(NSMenuItem.separator())
 #endif

DuckDuckGo/Updates/ReleaseNotesTabExtension.swift

@@ -133,7 +133,7 @@ extension ReleaseNotesValues {
          releaseNotes: [String]? = nil,
          releaseNotesPrivacyPro: [String]? = nil,
          downloadProgress: Double? = nil,
-         automaticUpdate: Bool? = nil) {
+         automaticUpdate: Bool?) {
         self.status = status.rawValue
         self.currentVersion = currentVersion
         self.latestVersion = latestVersion
@@ -145,14 +145,15 @@ extension ReleaseNotesValues {
         self.automaticUpdate = automaticUpdate
     }
 
-    init(from updateController: UpdateController?) {
+    init(from updateController: UpdateController) {
         let currentVersion = "\(AppVersion().versionNumber) (\(AppVersion().buildNumber))"
-        let lastUpdate = UInt((updateController?.lastUpdateCheckDate ?? Date()).timeIntervalSince1970)
+        let lastUpdate = UInt((updateController.lastUpdateCheckDate ?? Date()).timeIntervalSince1970)
 
-        guard let updateController, let latestUpdate = updateController.latestUpdate else {
-            self.init(status: updateController?.updateProgress.toStatus ?? .loaded,
+        guard let latestUpdate = updateController.latestUpdate else {
+            self.init(status: updateController.updateProgress.toStatus,
                       currentVersion: currentVersion,
-                      lastUpdate: lastUpdate)
+                      lastUpdate: lastUpdate,
+                      automaticUpdate: updateController.areAutomaticUpdatesEnabled)
             return
         }
 
@@ -194,11 +195,11 @@ private extension Update {
 private extension UpdateCycleProgress {
     var toStatus: ReleaseNotesValues.Status {
         switch self {
-        case .updateCycleDidStart: return .loading
+        case .updateCycleNotStarted, .updateCycleDidStart: return .loading
         case .downloadDidStart, .downloading: return .updateDownloading
         case .extractionDidStart, .extracting, .readyToInstallAndRelaunch, .installationDidStart, .installing: return .updatePreparing
         case .updaterError: return .updateError
-        case .updateCycleNotStarted, .updateCycleDone: return .updateReady
+        case .updateCycleDone: return .loaded
         }
     }
 

DuckDuckGo/Updates/ReleaseNotesUserScript.swift

@@ -77,7 +77,10 @@ final class ReleaseNotesUserScript: NSObject, Subfeature {
             return
         }
 
-        let updateController = Application.appDelegate.updateController
+        guard let updateController = Application.appDelegate.updateController else {
+            return
+        }
+
         let values = ReleaseNotesValues(from: updateController)
         broker?.push(method: "onUpdate", params: values, for: self, into: webView)
     }

DuckDuckGo/Updates/UpdateController.swift

@@ -105,7 +105,7 @@ final class UpdateController: NSObject, UpdateControllerProtocol {
     @UserDefaultsWrapper(key: .automaticUpdates, defaultValue: true)
     var areAutomaticUpdatesEnabled: Bool {
         didSet {
-            Logger.updates.log("areAutomaticUpdatesEnabled: \(self.areAutomaticUpdatesEnabled)")
+            Logger.updates.log("areAutomaticUpdatesEnabled: \(self.areAutomaticUpdatesEnabled, privacy: .public)")
             if oldValue != areAutomaticUpdatesEnabled {
                 userDriver?.cancelAndDismissCurrentUpdate()
                 try? configureUpdater()
@@ -239,7 +239,7 @@ extension UpdateController: SPUUpdaterDelegate {
     }
 
     func updater(_ updater: SPUUpdater, didAbortWithError error: Error) {
-        Logger.updates.error("Updater did abort with error: \(error.localizedDescription)")
+        Logger.updates.error("Updater did abort with error: \(error.localizedDescription, privacy: .public) (\(error.pixelParameters, privacy: .public))")
         let errorCode = (error as NSError).code
         guard ![Int(Sparkle.SUError.noUpdateError.rawValue),
                 Int(Sparkle.SUError.installationCanceledError.rawValue),
@@ -252,7 +252,7 @@ extension UpdateController: SPUUpdaterDelegate {
     }
 
     func updater(_ updater: SPUUpdater, didFindValidUpdate item: SUAppcastItem) {
-        Logger.updates.log("Updater did find valid update: \(item.displayVersionString)(\(item.versionString))")
+        Logger.updates.log("Updater did find valid update: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
         PixelKit.fire(DebugEvent(GeneralPixel.updaterDidFindUpdate))
         cachedUpdateResult = UpdateCheckResult(item: item, isInstalled: false)
     }
@@ -261,7 +261,7 @@ extension UpdateController: SPUUpdaterDelegate {
         let nsError = error as NSError
         guard let item = nsError.userInfo[SPULatestAppcastItemFoundKey] as? SUAppcastItem else { return }
 
-        Logger.updates.log("Updater did not find update: \(String(describing: item.displayVersionString))(\(String(describing: item.versionString)))")
+        Logger.updates.log("Updater did not find valid update: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
         PixelKit.fire(DebugEvent(GeneralPixel.updaterDidNotFindUpdate, error: error))
 
         // Edge case: User upgrades to latest version within their rollout group
@@ -274,30 +274,51 @@ extension UpdateController: SPUUpdaterDelegate {
     }
 
     func updater(_ updater: SPUUpdater, didDownloadUpdate item: SUAppcastItem) {
-        Logger.updates.log("Updater did download update: \(item.displayVersionString)(\(item.versionString))")
+        Logger.updates.log("Updater did download update: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
         PixelKit.fire(DebugEvent(GeneralPixel.updaterDidDownloadUpdate))
     }
 
     func updater(_ updater: SPUUpdater, didExtractUpdate item: SUAppcastItem) {
-        Logger.updates.log("Updater did extract update: \(item.displayVersionString)(\(item.versionString))")
+        Logger.updates.log("Updater did extract update: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
     }
 
     func updater(_ updater: SPUUpdater, willInstallUpdate item: SUAppcastItem) {
-        Logger.updates.log("Updater will install update: \(item.displayVersionString)(\(item.versionString))")
+        Logger.updates.log("Updater will install update: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
+    }
+
+    func updater(_ updater: SPUUpdater, willInstallUpdateOnQuit item: SUAppcastItem, immediateInstallationBlock immediateInstallHandler: @escaping () -> Void) -> Bool {
+        Logger.updates.log("Updater will install update on quit: \(item.displayVersionString, privacy: .public)(\(item.versionString, privacy: .public))")
+        userDriver?.configureResumeBlock(immediateInstallHandler)
+        return true
     }
 
     func updater(_ updater: SPUUpdater, didFinishUpdateCycleFor updateCheck: SPUUpdateCheck, error: (any Error)?) {
         if error == nil {
-            Logger.updates.log("Updater did finish update cycle")
-            updateProgress = .updateCycleDone
+            Logger.updates.log("Updater did finish update cycle with no error")
+            updateProgress = .updateCycleDone(.finishedWithNoError)
         } else if let errorCode = (error as? NSError)?.code, errorCode == Int(Sparkle.SUError.noUpdateError.rawValue) {
             Logger.updates.log("Updater did finish update cycle with no update found")
-            updateProgress = .updateCycleDone
-        } else {
-            Logger.updates.log("Updater did finish update cycle with error")
+            updateProgress = .updateCycleDone(.finishedWithNoUpdateFound)
+        } else if let error {
+            Logger.updates.log("Updater did finish update cycle with error: \(error.localizedDescription, privacy: .public) (\(error.pixelParameters, privacy: .public))")
         }
     }
 
+    func log() {
+        Logger.updates.log("areAutomaticUpdatesEnabled: \(self.areAutomaticUpdatesEnabled, privacy: .public)")
+        Logger.updates.log("updateProgress: \(self.updateProgress, privacy: .public)")
+        if let cachedUpdateResult {
+            Logger.updates.log("cachedUpdateResult: \(cachedUpdateResult.item.displayVersionString, privacy: .public)(\(cachedUpdateResult.item.versionString, privacy: .public))")
+        }
+        if let state = userDriver?.sparkleUpdateState {
+            Logger.updates.log("Sparkle update state: (userInitiated:  \(state.userInitiated, privacy: .public), stage: \(state.stage.rawValue, privacy: .public))")
+        } else {
+            Logger.updates.log("Sparkle update state: Unknown")
+        }
+        if let userDriver {
+            Logger.updates.log("isResumable: \(userDriver.isResumable, privacy: .public)")
+        }
+    }
 }
 
 #endif

DuckDuckGo/Updates/UpdateNotificationPresenter.swift

@@ -26,7 +26,7 @@ final class UpdateNotificationPresenter {
     static let presentationTimeInterval: TimeInterval = 10
 
     func showUpdateNotification(icon: NSImage, text: String, buttonText: String? = nil, presentMultiline: Bool = false) {
-        Logger.updates.log("Notification presented: \(text)")
+        Logger.updates.log("Notification presented: \(text, privacy: .public)")
 
         DispatchQueue.main.async {
             guard let windowController = WindowControllersManager.shared.lastKeyMainWindowController ?? WindowControllersManager.shared.mainWindowControllers.last,

DuckDuckGo/Updates/UpdateUserDriver.swift

@@ -40,10 +40,19 @@ enum UpdateState {
     }
 }
 
-enum UpdateCycleProgress {
+enum UpdateCycleProgress: CustomStringConvertible {
+    enum DoneReason: Int {
+        case finishedWithNoError = 100
+        case finishedWithNoUpdateFound = 101
+        case pausedAtDownloadCheckpoint = 102
+        case pausedAtRestartCheckpoint = 103
+        case proceededToInstallationAtRestartCheckpoint = 104
+        case dismissedWithNoError = 105
+    }
+
     case updateCycleNotStarted
     case updateCycleDidStart
-    case updateCycleDone
+    case updateCycleDone(DoneReason)
     case downloadDidStart
     case downloading(Double)
     case extractionDidStart
@@ -75,19 +84,39 @@ enum UpdateCycleProgress {
         default: return false
         }
     }
+
+    var description: String {
+        switch self {
+        case .updateCycleNotStarted: return "updateCycleNotStarted"
+        case .updateCycleDidStart: return "updateCycleDidStart"
+        case .updateCycleDone(let reason): return "updateCycleDone(\(reason.rawValue))"
+        case .downloadDidStart: return "downloadDidStart"
+        case .downloading(let percentage): return "downloading(\(percentage))"
+        case .extractionDidStart: return "extractionDidStart"
+        case .extracting(let percentage): return "extracting(\(percentage))"
+        case .readyToInstallAndRelaunch: return "readyToInstallAndRelaunch"
+        case .installationDidStart: return "installationDidStart"
+        case .installing: return "installing"
+        case .updaterError(let error): return "updaterError(\(error.localizedDescription))(\(error.pixelParameters))"
+        }
+    }
 }
 
 final class UpdateUserDriver: NSObject, SPUUserDriver {
     enum Checkpoint: Equatable {
-        case download
-        case restart
+        case download // for manual updates, pause the process before downloading the update
+        case restart // for automatic updates, pause the process before attempting to restart
     }
 
     private var internalUserDecider: InternalUserDecider
 
     private var checkpoint: Checkpoint
+
+    // Resume the update process when the user explicitly chooses to do so
     private var onResuming: (() -> Void)?
-    private var onSkipping: () -> Void = {}
+
+    // Dismiss the current update for the time being but keep the downloaded file around
+    private var onDismiss: () -> Void = {}
 
     var isResumable: Bool {
         onResuming != nil
@@ -99,6 +128,8 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
     @Published var updateProgress = UpdateCycleProgress.default
     var updateProgressPublisher: Published<UpdateCycleProgress>.Publisher { $updateProgress }
 
+    private(set) var sparkleUpdateState: SPUUserUpdateState?
+
     init(internalUserDecider: InternalUserDecider,
          areAutomaticUpdatesEnabled: Bool) {
         self.internalUserDecider = internalUserDecider
@@ -109,8 +140,13 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
         onResuming?()
     }
 
+    func configureResumeBlock(_ block: @escaping () -> Void) {
+        guard !isResumable else { return }
+        onResuming = block
+    }
+
     func cancelAndDismissCurrentUpdate() {
-        onSkipping()
+        onDismiss()
     }
 
     func show(_ request: SPUUpdatePermissionRequest) async -> SUUpdatePermissionResponse {
@@ -122,21 +158,27 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
     }
 
     func showUserInitiatedUpdateCheck(cancellation: @escaping () -> Void) {
-        Logger.updates.log("Updater started performing the update check. (isInternalUser: \(self.internalUserDecider.isInternalUser)")
+        Logger.updates.log("Updater started performing the update check. (isInternalUser: \(self.internalUserDecider.isInternalUser, privacy: .public))")
         updateProgress = .updateCycleDidStart
     }
 
     func showUpdateFound(with appcastItem: SUAppcastItem, state: SPUUserUpdateState, reply: @escaping (SPUUserUpdateChoice) -> Void) {
+        Logger.updates.log("Updater shown update found: (userInitiated:  \(state.userInitiated, privacy: .public), stage: \(state.stage.rawValue, privacy: .public))")
+        sparkleUpdateState = state
+
         if appcastItem.isInformationOnlyUpdate {
+            Logger.updates.log("Updater dismissed due to information only update")
             reply(.dismiss)
         }
 
-        onSkipping = { reply(.skip) }
+        onDismiss = { reply(.dismiss) }
 
         if checkpoint == .download {
             onResuming = { reply(.install) }
-            updateProgress = .updateCycleDone
+            updateProgress = .updateCycleDone(.pausedAtDownloadCheckpoint)
+            Logger.updates.log("Updater paused at download checkpoint (manual update pending user decision)")
         } else {
+            Logger.updates.log("Updater proceeded to installation at download checkpoint")
             reply(.install)
         }
     }
@@ -154,11 +196,13 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
     }
 
     func showUpdaterError(_ error: any Error, acknowledgement: @escaping () -> Void) {
+        Logger.updates.error("Updater encountered an error: \(error.localizedDescription, privacy: .public) (\(error.pixelParameters, privacy: .public))")
         updateProgress = .updaterError(error)
         acknowledgement()
     }
 
     func showDownloadInitiated(cancellation: @escaping () -> Void) {
+        Logger.updates.log("Updater started downloading the update")
         updateProgress = .downloadDidStart
     }
 
@@ -176,6 +220,7 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
     }
 
     func showDownloadDidStartExtractingUpdate() {
+        Logger.updates.log("Updater started extracting the update")
         updateProgress = .extractionDidStart
     }
 
@@ -184,19 +229,27 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
     }
 
     func showReady(toInstallAndRelaunch reply: @escaping (SPUUserUpdateChoice) -> Void) {
-        onSkipping = { reply(.skip) }
+        onDismiss = { reply(.dismiss) }
 
         if checkpoint == .restart {
             onResuming = { reply(.install) }
+            updateProgress = .updateCycleDone(.pausedAtRestartCheckpoint)
+            Logger.updates.log("Updater paused at restart checkpoint (automatic update pending user decision)")
         } else {
             reply(.install)
+            updateProgress = .updateCycleDone(.proceededToInstallationAtRestartCheckpoint)
+            Logger.updates.log("Updater proceeded to installation at restart checkpoint")
         }
-
-        updateProgress = .updateCycleDone
     }
 
     func showInstallingUpdate(withApplicationTerminated applicationTerminated: Bool, retryTerminatingApplication: @escaping () -> Void) {
+        Logger.updates.info("Updater started the installation")
         updateProgress = .installationDidStart
+
+        if !applicationTerminated {
+            Logger.updates.log("Updater re-sent a quit event")
+            retryTerminatingApplication()
+        }
     }
 
     func showUpdateInstalledAndRelaunched(_ relaunched: Bool, acknowledgement: @escaping () -> Void) {
@@ -210,7 +263,7 @@ final class UpdateUserDriver: NSObject, SPUUserDriver {
 
     func dismissUpdateInstallation() {
         guard !updateProgress.isFailed else { return }
-        updateProgress = .updateCycleDone
+        updateProgress = .updateCycleDone(.dismissedWithNoError)
     }
 }