From 6cc43c9fd4abea112f222c8ef8d7265740c49c24 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Mon, 2 Nov 2026 13:17:03 +1100 Subject: [PATCH] test(mobile): report host hop latency when a push snapshot callback times out Follow-up to 885804282 from its review. That commit added a class-level `BuzzTestHostSettleBarrier` that measured a user-initiated-queue-then-main hop in `setUp` and let the class start once three consecutive hops were fast. Re-reading both 2026-11-01 CI logs showed the barrier would have opened immediately in both failing runs: in job 124905175903 the one-hop test `testAllowedNotificationRestoreNeedsNoAppGroupStore` passed in 0.070 s at the start of the class, and 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 one-instant gate cannot cover, and a sustained-hop version would be a CI-only wait. The barrier, its doc comment with the measurement figures, and its "settled/gave up" print are removed. The per-element QoS assertion from 885804282 and everything from f0bf2c0c8 stay. In its place, a `waitForCallback` helper in `BuzzPushSnapshotEnrichmentTests` wraps the three callback waits in the two affected tests. It waits with `XCTWaiter` for the unchanged 10 s `callbackTimeout` and returns at once on success, costing nothing on a passing run. Only when the wait does not complete does it time one fresh user-initiated-queue-then-main-queue hop, the path every bridge reply follows, bounded at 2 s, and fail with the expectation's description plus the measured hop ("a fresh queue->main hop took 705.3 ms", "took 0.4 ms", or "did not finish within 2 s"). That lets a starved host be told apart from a callback that never fired the next time this appears in CI. The original assertions still run after the helper, so the nil-versus-reason evidence is unchanged. If this recurs, the remaining levers are the test host (RunnerTests boot the full Flutter app as TEST_HOST, which is what saturated the 3-vCPU runner) or the 10 s `callbackTimeout`. Verification (Xcode 27.2, iOS 26.2 simulator runtime, 16-core host): - Forced timeout, with temporary variants not committed: making the bridge's retry deletion never call back produced "'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 with the final code: 10/10 green, 0.1-0.5 s each. - Full RunnerTests bundle with CI's `-parallel-testing-enabled NO`: 2/2 green (101 tests, 24-29 s). - The commit touches only this test file; the pinned Dart formatter was first on PATH so the pre-commit hook reformatted nothing else. No swiftformat or swiftlint configuration in the repo; `git diff --check` is clean. Co-Authored-By: Claude Fable 5.1 Signed-off-by: Matt Toohey --- .../BuzzCommunicationNotificationTests.swift | 79 +++++++------------ 1 file changed, 27 insertions(+), 52 deletions(-) diff --git a/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift b/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift index e3e1317d33..9f3f9b06b4 100644 --- a/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift +++ b/mobile/ios/RunnerTests/BuzzCommunicationNotificationTests.swift @@ -242,61 +242,36 @@ final class BuzzCommunicationNotificationTests: XCTestCase { } } -/// RunnerTests load the full Flutter app as their host. On CI's 3-vCPU runners -/// its launch saturated the machine for about 40 s (both 2026-11-01 failures): -/// a trivial queue-to-main hop took 1.3 s, then over 10 s, while a synchronous -/// main-thread test slowed from 0.013 s to 2.65 s, and the bridge's replies -/// missed their 10 s waits. This barrier measures that same hop, at the QoS -/// the bridge uses, and lets the class begin only once three consecutive hops -/// are fast again. On an idle host it costs a few milliseconds. The cap keeps a -/// host that never settles from hanging the run; its tests then fail with the -/// real symptom, and the printed line says the barrier gave up. -enum BuzzTestHostSettleBarrier { - /// A hop this slow leaves too little margin under the class's 10 s waits. - static let slowHop: TimeInterval = 0.5 - static let consecutiveFastHops = 3 - static let cap: TimeInterval = 60 - - /// Waits once per process; later calls return immediately. - static func waitUntilSettled() { - _ = settled - } - - private static let settled: Void = { - let queue = DispatchQueue(label: "xyz.block.buzz.test-host-settle", qos: .userInitiated) - let started = Date() - let deadline = started.addingTimeInterval(cap) - var fastHops = 0 - var slowHops = 0 - while fastHops < consecutiveFastHops, Date() < deadline { - let hopStarted = Date() - let hop = XCTestExpectation(description: "queue to main hop") - queue.async { DispatchQueue.main.async { hop.fulfill() } } - _ = XCTWaiter().wait(for: [hop], timeout: max(deadline.timeIntervalSinceNow, 0)) - if Date().timeIntervalSince(hopStarted) < slowHop { - fastHops += 1 - } else { - fastHops = 0 - slowHops += 1 - } - } - let outcome = fastHops < consecutiveFastHops ? "gave up" : "settled" - print( - "BuzzTestHostSettleBarrier \(outcome) after \(Date().timeIntervalSince(started)) s" - + " (\(slowHops) slow hops)" - ) - }() -} - /// Callbacks only record what they receive and assertions run after the wait, /// so a callback that lands after its test returned cannot fail a later test. /// The timeout is a cap; a passing test returns as soon as its callback runs. final class BuzzPushSnapshotEnrichmentTests: XCTestCase { private let callbackTimeout: TimeInterval = 10 - override class func setUp() { - super.setUp() - BuzzTestHostSettleBarrier.waitUntilSettled() + /// 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), so a starved test host ("hop took 7.2 s") + /// reads differently from a callback that never fired ("hop took 12 ms"). + /// Both 2026-11-01 CI failures were the former: 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() { @@ -406,7 +381,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) @@ -419,7 +394,7 @@ 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) @@ -459,7 +434,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)) }