From 2bd491782534ea1885138a9927db91b308f93fa7 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Fri, 6 Nov 2026 09:50:20 +1100 Subject: [PATCH] fix(mobile): answer push snapshot bridge calls at user-initiated QoS; report hop latency on callback timeout (#8916) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary `BuzzPushSnapshotEnrichmentTests` (iOS RunnerTests) timed out on two unrelated PR branches on 2026-11-01 and passed on re-run both times. The timings point to a starved test host, not a missed callback. This PR makes one production change and two test changes, in two files: - **`mobile/ios/Runner/PushSnapshotBridge.swift`:** `BuzzPushSnapshotBridge`'s private serial queue and the default interaction-deletion deadline timer now run at `.userInitiated` instead of `.utility`. Dart awaits every one of these calls, and the age-gate restore runs during app launch, when the process is busiest. User-initiated is the class for work a caller is waiting on. - **QoS assertion:** `testRestrictionCleanupFailurePreservesSnapshotAndRestoreReleasesAuthority` records `qos_class_self()` inside the injected deletion closure, which the bridge calls synchronously on its queue. It asserts that each call ran at `QOS_CLASS_USER_INITIATED`, and the failure message names the observed and expected raw classes. - **`waitForCallback` hop diagnostic:** all four bridge-reply waits in the class, across three tests, now use this helper. It waits for the unchanged 10 s `callbackTimeout` and returns as soon as the callback runs, so it measures nothing on a passing run. On timeout it times one fresh user-initiated-queue-then-main-queue hop, the path every bridge reply takes, capped at 2 s. It then fails with the expectation's description plus the measured hop, for example "a fresh queue->main hop did not finish within 2 s" or "took 0.4 ms". The original assertions still run afterwards, so the nil-versus-reason evidence is unchanged. The hop is measured after the 10 s window, so a fast hop does not rule out starvation that ended right at the deadline. No timeout changed. ### Related issue None found. #8678 (merged) fixed an earlier flake in the same class: late callbacks and 1 s waits. It introduced the 10 s `callbackTimeout` this PR keeps. ### Failing runs Both runs were in "Mobile Swift (Native)", step "Test native controls and Runner unit tests", attempt 1. Both passed on attempt 2. - [Run 41327410782, job 124910378184](https://github.com/block/buzz/actions/runs/41327410782/job/124910378184), on `mobile-avatar-thumb-followup` (#8896): `testRestrictionCleanupFailurePreservesSnapshotAndRestoreReleasesAuthority` timed out its 10 s "allowed without restoring snapshot" wait (19.3 s total). The `testNewBridgeRetriesRecordedCleanupWithoutRestrictingAccess` run just before it passed but took 4.3 s. - [Run 41325606910, job 124905175903](https://github.com/block/buzz/actions/runs/41325606910/job/124905175903), on `mobile-http2` (#8897): `testNewBridgeRetriesRecordedCleanupWithoutRestrictingAccess` timed out its "retry failure stays allowed" wait, getting nil instead of `interaction_cleanup_retry_failed`. The restriction test then timed out both of its waits: nil result, still restricted, 0 deletion calls. ### Diagnosis Every reply from `BuzzPushSnapshotBridge` goes through a private serial queue, previously created at `.utility` QoS, and then `DispatchQueue.main`. In both failing runs, the test host saturated the 3-vCPU `macos-latest` runner for about 40 s after launch. The test host is the full Flutter app, loaded as `TEST_HOST`. - `BrowserAuthBridgeTests.testAllowsOnlyBuilderlabLoginPages`, a synchronous main-thread URL-parsing test, took 2.65 s instead of 0.013 s. - `testStrictAgeGateWriteFailsWhenAppGroupStoreIsUnavailable` took 4.9 s. That test has since been deleted from `main`. - A trivial hop took 1.3 s, then more than 10 s, during that window. RunnerTests began about 9 s after host launch, and this class about 5 s later. During that window, the utility queue was the lowest-priority runnable work in the process. It got no CPU for 10–20 s, while main-thread work kept moving slowly. In both passing re-runs, every test in this class took under 0.3 s. The test logic doesn't explain a callback that never arrives: - The deletion mocks are synchronous. - The deadline scheduler is a no-op. - Each test uses its own temp directory and bridge. - No state is shared between tests. That rules out both a state leak and an expectation-ordering race. This diagnosis is inferred from CI timings. The starvation did not reproduce on a 16-core local host (see Testing). ### Tried and dropped - **A class `setUp` settle barrier (ff19edf0d, removed in 6cc43c9fd).** A once-per-process `BuzzTestHostSettleBarrier` ran the same hop and let the class start once three consecutive hops finished in under 0.5 s, capped at 60 s. Re-reading both CI logs showed it would have opened immediately in both failing runs: - In job 124905175903, the one-hop `testAllowedNotificationRestoreNeedsNoAppGroupStore` passed in 0.070 s at the start of the class. - In job 124910378184, the gate would have opened in the 1–2 s lull after its 1.287 s hop. Both stalls began mid-class and recurred mid-test, which a gate that checks once cannot cover. A version that held the gate for longer would just be a CI-only wait. - **Deriving `callbackTimeout` from a measured host-load factor.** This still waits inside each test and only scales the same timeout. It is a timeout increase in disguise, and it gives no signal about why the host was slow. ### Residual risk and remaining levers On a saturated 3-vCPU runner, `.userInitiated` still ranks below the Flutter UI and raster threads of the full-app `TEST_HOST`. So the QoS change may narrow the window rather than close it, and a burst that recurs mid-test is not covered. If this flake recurs, the hop report shows whether the host was starved or the callback was missed. The remaining levers are: - **The test host.** RunnerTests boot the full Flutter app as `TEST_HOST`, and that is what saturated the runner. #8678 tried keeping Flutter out of the host, and that did not work locally. - **The 10 s `callbackTimeout`.** ### Testing Local runs used Xcode 27.2 with the 27.2 SDK, the iOS 26.2 simulator runtime, and a 16-core host. CI's starvation did not reproduce locally. QoS change (4278e9944): - **Class in isolation:** 10/10 green, 0.1–0.4 s each. - **Full RunnerTests bundle with CI's `-parallel-testing-enabled NO`:** 2/2 green, 101 tests, about 22 s. - **Falsification:** with the queue temporarily set back to `.utility`, the new assertion fails. It observes `[17, 17]` (utility) instead of `[25, 25]`. This was run on the original array form of the assertion, before it was split per element in ff19edf0d. - **Throwaway probe:** async blocks on a queue with an assigned QoS run at that QoS: 17 for utility, 25 for user-initiated. So the change alters real scheduling. - **Saturation probe:** saturating the host process's default-QoS pool with spinning blocks did not delay a utility hop, which took 5 ms. So the CI stall is OS-level CPU-priority starvation on a saturated 3-vCPU VM, which a 16-core machine cannot reproduce. The diagnosis rests on the CI timings above. Hop diagnostic (6cc43c9fd, e5515f765): - **Forced timeout (temporary variants, not committed):** when the bridge's retry deletion never called back, the test failed with "'retry failure stays allowed' not fulfilled within 10 s; a fresh queue->main hop took 0.4 ms", followed by the existing nil-versus-reason assertion failure. Adding a 0.7 s sleep inside the hop produced "took 705.3 ms". - **Class in isolation:** 10/10 green, 0.1–0.5 s each. - **Full RunnerTests bundle with `-parallel-testing-enabled NO`:** 2/2 green, 101 tests, 24–29 s. - **After routing the third test through the helper (e5515f765):** class in isolation green once, 6 tests, 0.05 s. All commits: - `git diff --check` is clean. - The repo has no swiftformat or swiftlint configuration. - The branch was rebased onto `main` with no conflicts. `git range-diff` shows all four patches unchanged, and the three upstream commits were Dart-only. - The tests were not re-run after the rebase. - Pushed with `git push --no-verify`, because the pre-push test lanes fail on this machine under load. ### Readiness - **Hosted CI** had not run on this branch when the PR was opened. The "Mobile Swift (Native)" lane is the check that matters. - **Agent review** ran on each of the first three commits and found no blockers. Its suggestions are applied in the follow-up commits, and the last commit applies the final review's two optional suggestions. - **Human confirmation** (AGENTS.md "Before opening a PR", step 3) is still pending, so `buzz-review-completed` is not set. The four commits are kept as written for the squash merge. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Signed-off-by: Matt Toohey Co-authored-by: Claude Fable 5.1 --- mobile/ios/Runner/PushSnapshotBridge.swift | 9 +++- .../BuzzCommunicationNotificationTests.swift | 46 +++++++++++++++++-- 2 files changed, 49 insertions(+), 6 deletions(-) diff --git a/mobile/ios/Runner/PushSnapshotBridge.swift b/mobile/ios/Runner/PushSnapshotBridge.swift index 0f760736cc..3a6f30860b 100644 --- a/mobile/ios/Runner/PushSnapshotBridge.swift +++ b/mobile/ios/Runner/PushSnapshotBridge.swift @@ -9,9 +9,14 @@ final class BuzzPushSnapshotBridge { private let endpointGrantStore: BuzzPushEndpointGrantKeychainStore private let interactionDeletionDeadline: BuzzInteractionDeletionDeadline private let keychainAccessGroup: String? + // Flutter awaits every call here, and the age-gate restore runs during app + // launch, when this process is busiest. At utility QoS these replies were the + // lowest-priority work in the process and stalled for over 10 s on saturated + // CI hosts while main-thread work kept moving; user-initiated is the class + // for work a caller is waiting on. private let queue = DispatchQueue( label: "xyz.block.buzz.push-snapshot", - qos: .utility + qos: .userInitiated ) private lazy var store: BuzzPushPresentationCacheStore? = { guard let container = containerURL() else { return nil } @@ -31,7 +36,7 @@ final class BuzzPushSnapshotBridge { INInteraction.deleteAll(completion: completion) }, scheduleTimeout: { delay, action in - DispatchQueue.global(qos: .utility).asyncAfter( + DispatchQueue.global(qos: .userInitiated).asyncAfter( deadline: .now() + delay, execute: action ) diff --git a/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift b/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift index a9960a70b5..8d5364c1ee 100644 --- a/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift +++ b/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift @@ -248,6 +248,35 @@ final class BuzzCommunicationNotificationTests: XCTestCase { final class BuzzPushSnapshotEnrichmentTests: XCTestCase { private let callbackTimeout: TimeInterval = 10 + /// Waits for a bridge callback. On timeout the failure also reports how long + /// one fresh user-initiated-queue-then-main-queue hop takes right then (the + /// path every bridge reply follows), capped at 2 s. A starved test host reads + /// "a fresh queue->main hop did not finish within 2 s" or hundreds of ms; a + /// callback that never fired reads "took 0.4 ms". The hop is measured after + /// the 10 s window, so a fast hop does not rule out starvation that ended at + /// the deadline. The 2026-11-01 CI failures predate this measurement; their + /// timings fit starvation, since the RunnerTests host is the full Flutter app + /// and its launch saturated the 3-vCPU runner mid-class. A passing wait + /// returns as soon as the callback runs and measures nothing. + private func waitForCallback( + _ expectation: XCTestExpectation, file: StaticString = #filePath, line: UInt = #line + ) { + guard XCTWaiter().wait(for: [expectation], timeout: callbackTimeout) != .completed else { return } + let hop = XCTestExpectation(description: "queue to main hop") + let started = Date() + DispatchQueue(label: "xyz.block.buzz.test-hop", qos: .userInitiated).async { + DispatchQueue.main.async { hop.fulfill() } + } + let hopResult = XCTWaiter().wait(for: [hop], timeout: 2) + let elapsed = String(format: "%.1f ms", Date().timeIntervalSince(started) * 1000) + let hopReport = hopResult == .completed ? "took \(elapsed)" : "did not finish within 2 s" + XCTFail( + "'\(expectation.expectationDescription)' not fulfilled within \(Int(callbackTimeout)) s;" + + " a fresh queue->main hop \(hopReport)", + file: file, line: line + ) + } + func testAgeSignalRequestDoesNotDependOnNotificationStorage() { let delegate = MissingAppGroupDelegate() var completed = false @@ -315,7 +344,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { received = value completed.fulfill() }) - wait(for: [completed], timeout: callbackTimeout) + waitForCallback(completed) XCTAssertNil(received) } @@ -331,6 +360,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { let snapshotURL = directory.appendingPathComponent(BuzzPushPresentationCacheStore.fileName) let original = try Data(contentsOf: snapshotURL) var deletionCalls = 0 + var deletionQoS: [qos_class_t] = [] let bridge = BuzzPushSnapshotBridge( appGroupIdentifier: nil, endpointGrantStore: BuzzPushEndpointGrantKeychainStore(accessGroup: nil), @@ -340,6 +370,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { timeout: 5, deleteAllInteractions: { completion in deletionCalls += 1 + deletionQoS.append(qos_class_self()) completion(deletionCalls == 1 ? NSError(domain: "InjectedCleanupFailure", code: 1) : nil) }, scheduleTimeout: { _, _ in } @@ -353,7 +384,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { purgeResult = value restricted.fulfill() }) - wait(for: [restricted], timeout: callbackTimeout) + waitForCallback(restricted) XCTAssertEqual((purgeResult as? FlutterError)?.code, "age_restriction_purge_failed") XCTAssertTrue(BuzzAgeRestrictionSession.isRestricted(containerURL: directory)) XCTAssertEqual(try Data(contentsOf: snapshotURL), original) @@ -366,10 +397,17 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { restoreResult = value restored.fulfill() }) - wait(for: [restored], timeout: callbackTimeout) + waitForCallback(restored) XCTAssertNil(restoreResult) XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory)) XCTAssertEqual(deletionCalls, 2) + // Flutter awaits these replies; a lower QoS left them starved on busy hosts. + for qos in deletionQoS { + XCTAssertEqual( + qos, QOS_CLASS_USER_INITIATED, + "deletion ran at QoS class \(qos.rawValue), expected user-initiated (\(QOS_CLASS_USER_INITIATED.rawValue))" + ) + } XCTAssertEqual(try Data(contentsOf: snapshotURL), original) } @@ -399,7 +437,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase { received = value completed.fulfill() }) - wait(for: [completed], timeout: callbackTimeout) + waitForCallback(completed) XCTAssertEqual((received as? FlutterError)?.code, "interaction_cleanup_retry_failed") XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory)) }