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 <noreply@anthropic.com>
Signed-off-by: Matt Toohey <contact@matttoohey.com>
This commit is contained in:
Matt Toohey
2026-11-02 13:17:03 +11:00
parent ff19edf0de
commit 6cc43c9fd4

View File

@@ -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))
}