diff --git a/Strand/Data/IntelligenceEngine.swift b/Strand/Data/IntelligenceEngine.swift index b286ce8473..6aad38f07a 100644 --- a/Strand/Data/IntelligenceEngine.swift +++ b/Strand/Data/IntelligenceEngine.swift @@ -771,7 +771,7 @@ final class IntelligenceEngine: ObservableObject { // state that skipped the capture and just cleared, which is exactly where #1681 lived. The // Kotlin post-offload gate makes the same point in its own words: "captured before the run, // written only on success". - let owedToken = RescoreBackgroundScheduler.markRescoreOwed() + let owedToken = RescoreBackgroundScheduler.markRescoreOwed(passStarting: true) // #899-A re-arm: clear the lock, then if a forced rescore was dropped while this pass held it, // run it ONCE. The flag is cleared BEFORE the re-invoke (a single re-arm), so a forced call landing // DURING the re-invoke re-arms it again but a quiet one does not , this can never recurse unbounded. diff --git a/Strand/Data/RescoreBackgroundPolicy.swift b/Strand/Data/RescoreBackgroundPolicy.swift index 30f68a1084..52e65fd085 100644 --- a/Strand/Data/RescoreBackgroundPolicy.swift +++ b/Strand/Data/RescoreBackgroundPolicy.swift @@ -86,10 +86,13 @@ enum RescoreBackgroundPolicy { /// it is not evidence of a killed pass; the engine re-arms one follow-up pass for a trigger that /// lands mid-run. Deferring instead recorded a newer debt, the running pass then finished without /// settling it (#1681), and every offload after that deferred on it. + /// - secondsSinceLastAttempt: how long ago the last pass STARTED, nil when unknown. An outstanding + /// debt defers only while that attempt is recent (`interruptedRetryCooldownSeconds`). static func decide(isBackground: Bool, isRealUpdate: Bool = true, rescoreAlreadyOwed: Bool, - passInProgress: Bool = false) -> Decision { + passInProgress: Bool = false, + secondsSinceLastAttempt: Double? = nil) -> Decision { guard isBackground else { return .run } guard isRealUpdate else { @@ -97,11 +100,22 @@ enum RescoreBackgroundPolicy { reason: "the backstop tick does not re-score while backgrounded; offloads run their own") } - if rescoreAlreadyOwed, !passInProgress { + if rescoreAlreadyOwed, !passInProgress, + let since = secondsSinceLastAttempt, since >= 0, since < interruptedRetryCooldownSeconds { return .deferToBackgroundTask( reason: "a re-score is already outstanding from an earlier trigger") } return .run } + + /// How long after an attempt that did not finish a backgrounded offload waits before trying again. + /// + /// Deferring on ANY outstanding debt, with no end, stopped scoring outright. A suspended app is + /// routinely terminated by iOS for memory, not CPU, so a pass interrupted that way is ordinary, and the + /// processing task it escalates to is granted rarely if ever. On one phone a pass left unfinished at + /// 11:25 deferred every offload until the app was next opened: 19 hours, with no score for the night + /// in between. Pacing (`backgroundRestPerWorkSecond`) is what keeps a background attempt under the CPU + /// limit now, so this only needs to stop a retry on every offload, not forever. + static let interruptedRetryCooldownSeconds: Double = 30 * 60 } diff --git a/Strand/System/RescoreBackgroundScheduler.swift b/Strand/System/RescoreBackgroundScheduler.swift index a971de04f4..4c8b158f24 100644 --- a/Strand/System/RescoreBackgroundScheduler.swift +++ b/Strand/System/RescoreBackgroundScheduler.swift @@ -73,14 +73,29 @@ enum RescoreBackgroundScheduler { return value.isFinite && value > 0 ? value : nil } + /// When the last pass started (unix seconds), written only by a pass that is about to work, never by + /// the deferral path, so repeated deferrals cannot keep a stale debt looking fresh. + static let lastAttemptStartedAtKey = "noop.rescoreLastAttemptStartedAt" + + /// Seconds since the last pass started, nil if none was ever recorded. + static var secondsSinceLastAttempt: Double? { + let started = UserDefaults.standard.double(forKey: lastAttemptStartedAtKey) + return started > 0 ? Date().timeIntervalSince1970 - started : nil + } + /// Mark a re-score as owed. Called by `IntelligenceEngine` once a pass is past every gate and is /// definitely about to work — so that a kill leaves the debt behind — and by the deferral path, where /// no pass is attempted at all but the work is just as outstanding. /// Returns the token stamped on this debt. A pass keeps it and hands it back at completion; every /// other caller (the deferral path) can ignore it, since it is not the one that will settle up. + /// - Parameter passStarting: the caller is a pass about to work (not the deferral path), so the attempt + /// time is recorded for `RescoreBackgroundPolicy.interruptedRetryCooldownSeconds`. @discardableResult - static func markRescoreOwed() -> String { + static func markRescoreOwed(passStarting: Bool = false) -> String { let token = UUID().uuidString + if passStarting { + UserDefaults.standard.set(Date().timeIntervalSince1970, forKey: lastAttemptStartedAtKey) + } UserDefaults.standard.set(true, forKey: owedKey) UserDefaults.standard.set(token, forKey: owedTokenKey) // A fresh debt is unproven until the pass that owns it finishes: if THIS pass is killed, the @@ -175,7 +190,8 @@ enum RescoreBackgroundScheduler { isBackground: isBackground ?? isBackgrounded, isRealUpdate: owesOnDefer, rescoreAlreadyOwed: isRescoreOwed, - passInProgress: passInProgress) + passInProgress: passInProgress, + secondsSinceLastAttempt: secondsSinceLastAttempt) switch decision { case .deferToBackgroundTask(let reason): diff --git a/StrandTests/RescoreBackgroundPolicyTests.swift b/StrandTests/RescoreBackgroundPolicyTests.swift index 0958545db1..e7ff529ea2 100644 --- a/StrandTests/RescoreBackgroundPolicyTests.swift +++ b/StrandTests/RescoreBackgroundPolicyTests.swift @@ -14,11 +14,13 @@ final class RescoreBackgroundPolicyTests: XCTestCase { private func decide(background: Bool = true, realUpdate: Bool = true, unfinished: Bool = false, - running: Bool = false) -> RescoreBackgroundPolicy.Decision { + running: Bool = false, + attemptedSecondsAgo: Double? = 60) -> RescoreBackgroundPolicy.Decision { RescoreBackgroundPolicy.decide(isBackground: background, isRealUpdate: realUpdate, rescoreAlreadyOwed: unfinished, - passInProgress: running) + passInProgress: running, + secondsSinceLastAttempt: attemptedSecondsAgo) } private func isDeferred(_ d: RescoreBackgroundPolicy.Decision) -> Bool { @@ -53,6 +55,16 @@ final class RescoreBackgroundPolicyTests: XCTestCase { XCTAssertTrue(isDeferred(decide(unfinished: true))) } + /// ...but only for a while. A suspended app is routinely terminated for memory, so an unfinished pass + /// is ordinary; deferring on it forever left a night unscored for 19 hours on one phone. + func testAnInterruptedAttemptIsRetriedOnceTheCooldownHasPassed() { + let cooldown = RescoreBackgroundPolicy.interruptedRetryCooldownSeconds + XCTAssertTrue(isDeferred(decide(unfinished: true, attemptedSecondsAgo: cooldown - 1))) + XCTAssertEqual(decide(unfinished: true, attemptedSecondsAgo: cooldown), .run) + // No recorded attempt (an install from before the attempt time existed) is not a recent one. + XCTAssertEqual(decide(unfinished: true, attemptedSecondsAgo: nil), .run) + } + /// A pass running in THIS process reads as owed through its own started-mark. That is not a killed /// pass, and deferring on it recorded a newer debt the running pass could then never settle (#1681), /// so every later offload deferred too. The engine re-arms a follow-up pass for a mid-run trigger. diff --git a/StrandTests/RescoreBackgroundSchedulerTests.swift b/StrandTests/RescoreBackgroundSchedulerTests.swift index e7cd43a06e..65cfbf8286 100644 --- a/StrandTests/RescoreBackgroundSchedulerTests.swift +++ b/StrandTests/RescoreBackgroundSchedulerTests.swift @@ -15,6 +15,7 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { private var savedSeconds: Any? private var savedToken: Any? private var savedAfterCompleted: Any? + private var savedAttemptAt: Any? override func setUp() { super.setUp() @@ -25,6 +26,8 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { savedToken = UserDefaults.standard.object(forKey: RescoreBackgroundScheduler.owedTokenKey) savedAfterCompleted = UserDefaults.standard.object( forKey: RescoreBackgroundScheduler.owedAfterCompletedPassKey) + savedAttemptAt = UserDefaults.standard.object(forKey: RescoreBackgroundScheduler.lastAttemptStartedAtKey) + UserDefaults.standard.removeObject(forKey: RescoreBackgroundScheduler.lastAttemptStartedAtKey) UserDefaults.standard.removeObject(forKey: RescoreBackgroundScheduler.owedKey) UserDefaults.standard.removeObject(forKey: RescoreBackgroundScheduler.lastPassSecondsKey) UserDefaults.standard.removeObject(forKey: RescoreBackgroundScheduler.owedTokenKey) @@ -36,6 +39,7 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { restore(savedSeconds, RescoreBackgroundScheduler.lastPassSecondsKey) restore(savedToken, RescoreBackgroundScheduler.owedTokenKey) restore(savedAfterCompleted, RescoreBackgroundScheduler.owedAfterCompletedPassKey) + restore(savedAttemptAt, RescoreBackgroundScheduler.lastAttemptStartedAtKey) super.tearDown() } @@ -76,8 +80,8 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { /// The bug this file exists for: deferring has to record the debt, or the background task it defers /// to has nothing to find. func testDeferringMarksTheWorkOwedAndDoesNotRunIt() async { - // An earlier pass was killed: its mark is set and nothing runs now, so the policy defers. - let killedToken = RescoreBackgroundScheduler.markRescoreOwed() + // An earlier pass was killed moments ago: its mark is set and nothing runs now, so the policy defers. + let killedToken = RescoreBackgroundScheduler.markRescoreOwed(passStarting: true) var ran = false var logged: [String] = [] @@ -122,7 +126,7 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { /// is the livelock fix: #1538 paid for a full eight-minute pass on every offload because nothing /// remembered that the previous one had not finished. func testASecondBackgroundTriggerDoesNotStartADuplicatePass() async { - RescoreBackgroundScheduler.markRescoreOwed() + RescoreBackgroundScheduler.markRescoreOwed(passStarting: true) var ran = false await RescoreBackgroundScheduler.run(isBackground: true, log: { _ in }) { ran = true } @@ -332,4 +336,16 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { XCTAssertNotEqual(x, 0) XCTAssertGreaterThan(RescoreBackgroundScheduler.processCPUSeconds() ?? 0, start) } + + /// Repeated deferrals re-mark the debt but must not refresh the attempt time, or an old unfinished pass + /// would look recent forever and every offload would keep deferring. + func testADeferralDoesNotMakeAnOldAttemptLookRecent() async { + RescoreBackgroundScheduler.markRescoreOwed(passStarting: true) + let old = Date().timeIntervalSince1970 - RescoreBackgroundPolicy.interruptedRetryCooldownSeconds - 60 + UserDefaults.standard.set(old, forKey: RescoreBackgroundScheduler.lastAttemptStartedAtKey) + RescoreBackgroundScheduler.markRescoreOwed() + var ran = false + await RescoreBackgroundScheduler.run(isBackground: true, log: { _ in }) { ran = true } + XCTAssertTrue(ran, "an attempt older than the cooldown is retried in the background") + } }