Skip to content

Fix flaky network observer test and harden notification delivery#2559

Merged
onevcat merged 3 commits into
masterfrom
fix/flaky-network-observer-test
Jul 19, 2026
Merged

Fix flaky network observer test and harden notification delivery#2559
onevcat merged 3 commits into
masterfrom
fix/flaky-network-observer-test

Conversation

@onevcat

@onevcat onevcat commented Jul 19, 2026

Copy link
Copy Markdown
Owner

Problem

RetryStrategyTests.testNetworkObserverNotifiesOnlyOnce fails intermittently on CI with:

Asynchronous wait failed: Exceeded timeout of 1 seconds, with unfulfilled expectations

Example: run 29687516319 (Xcode 26.2, iOS 26.2). A rerun reliably passes.

Root cause

A CI-side scheduler stall, not an implementation bug. In the same failing run, the neighboring testNetworkRetryStrategyWaitsForReconnection (nominally ~0.15s: one 0.1s asyncAfter plus a few queue hops) took 2.167 seconds - the runner VM stalled for ~2s right around the failure. The failing test's callback path hops through a .utility QoS serial queue before reaching main (~5ms when healthy), and its 1-second expectation budget is the only positive wait in the file that doesn't follow the timeout: 10 convention; it was seemingly copied from the inverted sibling test above it, where a short window is intentional.

Historical failures of the same test family (testNetworkRetryStrategyWaitsForReconnection / testNetworkRetryStrategyCancelsPreviousObserver, June, Xcode 26.5/26.0.1) all predate #2536-era fixes (7730ef18, b7ce92aa); after those landed, this 1s timeout is the only remaining flake, and the Xcode 26.2 correlation is a single-sample coincidence.

Changes

  • Test: bump testNetworkObserverNotifiesOnlyOnce wait from 1s to 10s, matching every other positive expectation in the file. The once-only contract is enforced by assertForOverFulfill, which is independent of the timeout value; waitForExpectations returns immediately on fulfillment, so the happy path stays milliseconds.
  • Hardening: NetworkObserverImpl.notify()/cancel() now capture self strongly in their async blocks. Previously, delivery of an already-scheduled one-shot notification depended on the caller happening to retain the observer until the block executed; dropping the last reference in that window silently swallowed the callback. The blocks are one-shot so the temporary strong capture cannot form a lasting cycle, and the timeout work item keeps its weak capture so a pending 30s timer never pins an abandoned observer. TestNetworkObserver mirrors the change.

Verification

On iPhone 17 / iOS 26.2 simulator, with all CPU cores saturated to try to reproduce the starvation:

  • Pre-fix repro attempt: 450 iterations of the observer-family tests - could not reproduce locally (the CI stall is hypervisor-level; diagnosis rests on the log evidence above)
  • Post-fix: 5 network observer tests x 100 iterations = 500/500 passed under full load
  • Full KingfisherTests suite: 388/388 passed
  • swift build (macOS/SPM): clean

onevcat added 2 commits July 20, 2026 00:18
testNetworkObserverNotifiesOnlyOnce used a 1-second expectation timeout,
the only positive wait in the file not using the 10-second convention.
Its callback path hops through a utility-QoS queue before reaching main,
so a multi-second scheduler stall on a loaded CI VM (evidenced by a
nominal 0.15s neighbor test taking 2.167s in the same failing run) blows
the budget. Align it with the rest of the file; the once-only contract
is still enforced by assertForOverFulfill.

Also capture self strongly in NetworkObserverImpl.notify/cancel blocks.
Delivery of an already-scheduled one-shot notification previously
depended on the caller happening to retain the observer until the async
block ran; a dropped reference silently swallowed the callback. The
blocks are one-shot so the temporary strong capture cannot cycle, and
the timeout work item stays weak so a pending timer does not pin an
abandoned observer. TestNetworkObserver mirrors the same change.
The PR run reproduced the same failure class on a different test
(testDidFinishDownloadingDelegateCalledOncePerErroredDownload, a local
Nocilla-stubbed test with a 3s budget): its suite shows 11.2s of CPU
time against 31.4s wall, i.e. ~20s of VM-level stalling. No per-test
timeout survives that, so inflating individual budgets is whack-a-mole.
Pass number_of_retries to scan (-retry-tests-on-failure) instead; green
runs are unaffected and a genuine regression still fails every attempt.
@onevcat

onevcat commented Jul 19, 2026

Copy link
Copy Markdown
Owner Author

The first CI round on this PR delivered a decisive extra data point: test (Xcode 26.2, iOS 26.2) failed again, but on a different test (ImageDownloaderTests.testDidFinishDownloadingDelegateCalledOncePerErroredDownload, 3s budget, local Nocilla stub), while the RetryStrategyTests fixed here passed 16/16.

The numbers from that job make the mechanism unambiguous: that suite executed 36 tests in 11.2s CPU / 31.4s wall (~20s of pure stall), and the whole bundle ran 387 tests in 55.3s CPU / 96.6s wall. The 26.2-iOS leg's runner stalls at hypervisor level for tens of seconds - no reasonable per-test timeout survives that, so bumping budgets one by one is whack-a-mole.

Added number_of_retries: 2 to the scan invocation (-retry-tests-on-failure): green runs are unaffected, stall victims get retried on a recovered machine, and a real regression still fails all three attempts.

Why this leg specifically: plausibly the macos-26 image ships with the newest simulator runtime warmed up, while the iOS 26.2 runtime needs first-boot dyld cache work that drags the whole VM - which also matches "rerun always passes" (second boot is warm).

Round-2 CI on the 26.2 leg turned three retries of
testNetworkRetryStrategyWaitsForReconnection into 10s timeouts while
neighboring tests passed in milliseconds, then delivered the callbacks
up to 36s late - misattributed into subsequent tests (XCTAssertNotNil
at line 407 reported inside testNetworkObserverDoesNotNotifyAfterCancel).
That is not a whole-VM stall: it is the per-observer utility-QoS serial
queue being starved for tens of seconds while default+ bands stay live.

The one-shot transition (flip isFinished, cancel the timer, deregister)
is a microsecond critical section; running it as an async hop on a
starvable queue opened an unbounded late-delivery window. Decide it
synchronously under NSLock and keep only the user-facing callback on
DispatchQueue.main. The utility queue leaves the delivery path entirely;
cancel-then-notify suppression now takes effect immediately instead of
relying on queue ordering. The timeout timer moves to the global utility
queue and funnels through the same atomic finish().

TestNetworkObserver mirrors the change. Monitor-side dispatch is
untouched: NetworkMonitor.removeObserver stays an async barrier (safe
from any thread) and TestNetworkMonitor's main-queue hop keeps notify
out of its sync-barrier critical section.
@onevcat

onevcat commented Jul 19, 2026

Copy link
Copy Markdown
Owner Author

Round 2 falsified the pure "runner stall" theory and pinpointed the real defect. Timeline from the failing job:

15:30:56  WaitsForReconnection attempt 1 -> 10s timeout (callback never arrived)
15:31:42  callback lands ~36s late, [weak context] already gone -> userInfo nil
          -> XCTAssertNotNil(line 407) explodes inside the *current* retry attempt
15:31:42  attempts 2 & 3 -> 10s timeouts each
15:31:43  their late callbacks land inside testNetworkObserverDoesNotNotifyAfterCancel
          -> two more misattributed line-407 failures

Neighboring tests passed in milliseconds throughout, so this is not a whole-VM stall: the per-observer .utility serial queue was starved for 10-36s while default+ QoS bands stayed responsive. Retry can't absorb that (all three attempts hit the same starvation), and no timeout budget survives it.

The defect is structural: the one-shot transition (flip isFinished, cancel the timer, deregister) is a microsecond critical section, but it ran as an async hop on a starvable queue - an unbounded window during which a finished/cancelled observer can still fire late into a later test. Fixed by deciding the transition synchronously under NSLock; only the user-facing callback is dispatched (still on main). The utility queue is gone from the delivery path, and cancel-then-notify suppression is now immediate rather than queue-order dependent.

Local verification (iPhone 17 / iOS 26.2): 30 iterations x full RetryStrategyTests = 480/480, full suite 387/387, SPM build clean.

@onevcat

onevcat commented Jul 19, 2026

Copy link
Copy Markdown
Owner Author

Verification status after the lock-based fix (17222407):

Round Code test (Xcode 26.2, iOS 26.2) Notes
master 2026-07-19 pre-PR FAIL testNetworkObserverNotifiesOnlyOnce, 1s budget
PR round 1 timeout fix + strong capture FAIL different victim (ImageDownloader, 3s budget), ~20s stall
PR round 2 + scan retries FAIL 3x10s timeouts + 36s-late callbacks -> root cause found
PR round 3 + lock-based one-shot PASS all 20 checks green
PR round 4 (rerun) same PASS all 8 jobs green

Plus locally on iPhone 17 / iOS 26.2: 30x full RetryStrategyTests (480/480) and the full suite (387/387).

The late-delivery failure mode is now structurally impossible (no starvable queue left in the delivery path); unrelated stall-induced timeouts in other suites are absorbed by -retry-tests-on-failure.

@onevcat
onevcat merged commit 2c2cc75 into master Jul 19, 2026
28 checks passed
@onevcat
onevcat deleted the fix/flaky-network-observer-test branch July 19, 2026 16:43
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant