mirror of
https://github.com/block/buzz.git
synced 2026-11-06 09:21:45 +00:00
fix(mobile): answer push snapshot bridge calls at user-initiated QoS; report hop latency on callback timeout (#8916)
## 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 in6cc43c9fd).** 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 inff19edf0d. - **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 <contact@matttoohey.com> Co-authored-by: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
@@ -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
|
||||
)
|
||||
|
||||
@@ -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))
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user