mirror of
https://github.com/block/buzz.git
synced 2026-11-06 09:21:45 +00:00
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:
@@ -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,
|
/// 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.
|
/// 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.
|
/// The timeout is a cap; a passing test returns as soon as its callback runs.
|
||||||
final class BuzzPushSnapshotEnrichmentTests: XCTestCase {
|
final class BuzzPushSnapshotEnrichmentTests: XCTestCase {
|
||||||
private let callbackTimeout: TimeInterval = 10
|
private let callbackTimeout: TimeInterval = 10
|
||||||
|
|
||||||
override class func setUp() {
|
/// Waits for a bridge callback. On timeout the failure also reports how long
|
||||||
super.setUp()
|
/// one fresh user-initiated-queue-then-main-queue hop takes right then (the
|
||||||
BuzzTestHostSettleBarrier.waitUntilSettled()
|
/// 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() {
|
func testAgeSignalRequestDoesNotDependOnNotificationStorage() {
|
||||||
@@ -406,7 +381,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase {
|
|||||||
purgeResult = value
|
purgeResult = value
|
||||||
restricted.fulfill()
|
restricted.fulfill()
|
||||||
})
|
})
|
||||||
wait(for: [restricted], timeout: callbackTimeout)
|
waitForCallback(restricted)
|
||||||
XCTAssertEqual((purgeResult as? FlutterError)?.code, "age_restriction_purge_failed")
|
XCTAssertEqual((purgeResult as? FlutterError)?.code, "age_restriction_purge_failed")
|
||||||
XCTAssertTrue(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
XCTAssertTrue(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
||||||
XCTAssertEqual(try Data(contentsOf: snapshotURL), original)
|
XCTAssertEqual(try Data(contentsOf: snapshotURL), original)
|
||||||
@@ -419,7 +394,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase {
|
|||||||
restoreResult = value
|
restoreResult = value
|
||||||
restored.fulfill()
|
restored.fulfill()
|
||||||
})
|
})
|
||||||
wait(for: [restored], timeout: callbackTimeout)
|
waitForCallback(restored)
|
||||||
XCTAssertNil(restoreResult)
|
XCTAssertNil(restoreResult)
|
||||||
XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
||||||
XCTAssertEqual(deletionCalls, 2)
|
XCTAssertEqual(deletionCalls, 2)
|
||||||
@@ -459,7 +434,7 @@ final class BuzzPushSnapshotEnrichmentTests: XCTestCase {
|
|||||||
received = value
|
received = value
|
||||||
completed.fulfill()
|
completed.fulfill()
|
||||||
})
|
})
|
||||||
wait(for: [completed], timeout: callbackTimeout)
|
waitForCallback(completed)
|
||||||
XCTAssertEqual((received as? FlutterError)?.code, "interaction_cleanup_retry_failed")
|
XCTAssertEqual((received as? FlutterError)?.code, "interaction_cleanup_retry_failed")
|
||||||
XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
XCTAssertFalse(BuzzAgeRestrictionSession.isRestricted(containerURL: directory))
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user