Skip to content

Harden six tests that failed on loaded machines - #127

Merged
whoisaldo merged 12 commits into
release/0.3.4-candidatefrom
fix/lossy-test-flake
Oct 30, 2026
Merged

whoisaldo merged 12 commits into
release/0.3.4-candidatefrom
fix/lossy-test-flake

Conversation

@whoisaldo

@whoisaldo whoisaldo commented Oct 29, 2026 •

Copy link
Copy Markdown
Member

Hardens six tests that failed on loaded machines or CI runners without anything being wrong in the product. Each fix keeps what the test proves, and the injected regressions below still fail. Load figures are devbox1's 1-minute load average (10 cores, shared with other builds) at the start of each run.

lossy_stream_recovers_and_adapts: the keyframe-storm assertion

What failed: one run of a full cargo test --workspace on devbox1 got 2 keyframe requests against a bound of 1.

Cause: the test, not a change in #116, #118, #119 or #123. Those PRs didn't touch this test's UDP keyframe path; #118's hold and larger pending window make requests rarer. The failed run's own trace shows the host's sender silent for 348 ms, then 605 ms, at load ~590. Each time a frame was waiting for its repair, the repairs arrived late, and the fake iPad gave up once the 100 ms stall allowance was spent, as the assembler specifies.

There is a second, test-only way to fail. The fake iPad stamped each datagram with the wall clock when it read it, and Reassembler::add_media ticks before inserting. So a test thread descheduled past a deadline expired a frame whose repair was already in its socket buffer.

Fix (host/tests/e2e_synthetic.rs):

  • Repair deadlines run on the fake iPad's own clock: each pass of the receive loop counts at most 20 ms. A pass waits 1 ms on macOS and 2 ms elsewhere (about 16 ms with Windows' timer), so on a machine with time to spare this clock is the wall clock, and a repair the host sends late is late on it too.
  • The capture clock was tried and is wrong the other way. Draining a backlog moves it hundreds of ms at once, past the deadlines of the gaps in that backlog. Under injected 300 ms receiver stalls it gave 11–28 requests per run, against base's 0.
  • A stall episode of a starved host may cost one request, at most 3 per run. Without one the bound stays at one request.
    • A host silence counts only when the host was starved: it lasts longer than two frame periods, the encoder finished at most the frame that ends it, and at most 3 encoded frames were unsent at its end (encode_frame_count and transport_packets_sent from the pipeline stats). A sender that stops on NACKs while the encoder keeps going builds up a backlog, its four-frame channel full plus one frame held, so its silences never count.
    • Silences add up per waiting frame, as the iPad's MAX_STALL_ALLOWANCE does. An episode is a frame whose starved silences pass the 100 ms allowance, so two 60–90 ms silences on one frame count too. The previous version counted only a single silence over 100 ms.
    • Reassembler::waiting_frames() (proto/src/reassembly.rs) is a new read-only accessor for the frames still missing fragments. Nothing else in the reassembler changed.

Injected regressions (temporary patches, not in this PR; a 64-deep decode queue in these runs so only the storm bound decides):

  • 150 ms sleep in send_repairs on 1 NACK in 15, encoder running: the new test fails, 3 requests and 0 stall episodes. The previous version of this PR passed the same injection: 3 requests ≤ 1 + 49 silences.
  • 1 NACK in 10: the new test fails on the storm bound (16 requests, 0 episodes). The previous version failed only on 97% decode, after excusing 18 requests with 67 silences.
  • Every NACK, or 1 in 5: both versions fail on sustained progress or 97% decode.
  • Whole-host starvation, sender and encoder stopped together: passes.
    • Three 400 ms stalls while a repair was due: 1 request, 3 episodes.
    • Two 400 ms stalls after a frame's first fragment: 0 requests, 2 episodes.
    • Two back-to-back 80 ms stalls: 0 requests, 2 episodes. Stop the USB keyframe spiral and wait for late repairs on Wi-Fi #118's hold keeps the newest frame through a full silence, so starvation rarely costs a request at all.

Loops: 30/30 passed at load 28–695 with 24 extra yes loops running. Every run had 0 requests; 2 runs counted one stall episode. After merging the candidate, 5/5 more passed at load 144–169.

hevc_stream_negotiates_and_decodes

What failed: on mainpc under load, HEVC counters must advance: [39, 1].

Cause: the known 3 s encoder-watchdog limitation. libx265 starved past it, the supervisor restarted the pipeline, and the new epoch numbers its pictures from 1 again.

Fix:

  • Counters must rise within each stream epoch.
  • At most two HEVC epochs. A second one is accepted only if exactly one restart happened since the first, and its logged reason is the encoder watchdog's (encoder silent for …). The test reads that reason from the supervisor's "automatic restart scheduled" log line.
  • The last epoch alone must decode WANT_DECODED_FRAMES. Short epochs no longer add up.
  • Every epoch after the handoff must start with an HEVC IRAP carrying parameter sets and the keyframe flag. So a restart passes only if the restarted stream negotiates HEVC again; a fallback to H.264 fails.
  • The 30 s wait is now a 120 s backstop. During a load spike to ~545, libx265 took 9 s for its first picture and made 18 pictures in 30 s, with no watchdog restart.

Injected faults (temporary patches):

  • An encoder that fails after every 10 frames: fails, with epochs [3, 4] and restart reason "injected repeated encoder fault". The previous version passed it with epochs [3, 4, 5, 6].
  • A single 3.5 s encoder stall: the watchdog restarts the pipeline, and the test passes with epochs [1, 2].

Loops: 30/30 passed at load 720–796 with 24 extra yes loops, every run a single epoch. After the merge, 5/5 more passed.

Reassembler clock in the HEVC and encoder-crash tests

Both tests used to give Reassembler::add_fragment the wall-clock read time. They now give it stream_time(origin, &header), the host's capture time for the frame (e2e_synthetic.rs, in each test's media branch). So the 100 ms expiry runs on the capture clock, as it already does in the pairing and preferred-FPS tests. A frame expires only once frames captured 100 ms after it arrive, never because the test thread was descheduled between two of its fragments. Neither test negotiates repair, so the repair-mode trap above doesn't apply.

encoder_crash_auto_restarts_and_stream_recovers

What failed: once at load ~590. The failure output wasn't kept, and 10 base runs at load ~700 passed.

Cause found by reading the test: the recovery gap started at the first 150 ms read timeout after 30 decoded frames. The fault fires at encoder frame 45, so on a machine slow enough to pause 150 ms between frames, the gap also counted the 15 frames streamed before the crash.

Fix: the gap now runs from the first epoch's last datagram to the second epoch's first, which is the freeze a user sees. The 5 s bound is unchanged.

Loops: 30/30 passed at load 22–1017. Each run had exactly one restart, for the injected fault.

updates::tests::the_failure_message_check_is_validated_and_bounded

Cause: the test required a 300 ms deadline to return within 450 ms. That leaves 150 ms of scheduling slack, which is tight on a loaded Windows runner.

Fix (host/src/updates/tests.rs): a 1 s deadline that must return within 1.3 s. That still rules out returning early, returning at a later limit (the 3 s FAILURE_CHECK, ureq's 10 s connect timeout), or a second wait as long as the first.

Loops: 30/30 passed at load 796–819; each run took 1.01 s.

AudioStreamTests (System E2E)

What failed: run 40840994468 on release/0.3.4-candidate (which includes #113), AudioStreamTests.swift:23: Disconnect did not appear within 5 s.

Cause: a race between the test and the display controls' 5 s auto-hide. Neither the app nor the simulator was late; the launch and the first "PC audio playing" took the usual time.

  • On the starved runner, the muted HUD label needed two 2 s polling rounds instead of one.
  • The test's single existence check then ran 4.3 s into the 5 s timer. It found Disconnect, so it made no reveal tap.
  • The controls hid about 0.6 s later, before the first evaluation of the 5 s wait, and nothing brought them back.
  • In passing runs the same check comes 2.0–2.4 s into the timer. A longer wait could not have helped.

Fix (ios/EternalMonitorUITests/AudioStreamTests.swift): waitForHUD's loop is now waitForControl. Until a 10 s deadline, it reveals the controls if the element is gone, then waits up to 2 s for the condition. The Disconnect check and the "Fill the screen" check, which had the same pattern, use it. The test still requires the session's Disconnect control and the pinned Fit setting after the live mute. The 5 s in the old wait was only a test timeout; no user-facing guarantee depends on it.

Run: scripts/test_ios.sh -only-testing:EternalMonitorUITests/AudioStreamTests passed on Xcode 16.4 with an iOS 18.6 iPad Pro 11 (M4) simulator, CI's pairing, at load 812–899.

CI: sudo mdutil -a -i off

What failed: "Prepare the disposable streaming runner" in System E2E. This happened in 2 of about 140 runs (40910597311 and 40597737798, first attempts). / and /System/Volumes/Data were switched off, but /System/Volumes/Preboot returned Error: unexpected indexing state. kMDConfigSearchLevelTransitioning, so the step exited 1.

Fix (.github/workflows/ci.yml): the command is retried up to five times, 5 s apart. A retry rather than continue-on-error, because:

  • the same step also shuts the simulators down, and continue-on-error would hide that failing too;
  • switching indexing off matters to the streaming timings this job measures, so it is worth getting;
  • the transitional state settles within seconds on a freshly booted VM.

Checks

On devbox1 at 1782fe9. The later merge of release/0.3.4-candidate at 791625c (#125) brings only workflow, installer and docs files.

  • cargo fmt --check passes.
  • cargo clippy --workspace --all-targets -- -D warnings passes.
  • cargo test --workspace passes: 835 tests, 0 failed.

The fake iPad stamped each datagram with the wall clock when it read it.
A test thread descheduled past a repair deadline read the repair late,
and Reassembler::add_media ticks before inserting, so the frame expired
with its repair already in the socket buffer. Each pass of the receive
loop now advances the iPad's clock by at most 20 ms. A pass waits at
most 1 ms on macOS and 2 ms elsewhere (about 16 ms with Windows' timer),
so on a machine with time to spare this is the wall clock, and a repair
the host sends late is still late. The capture clock was tried and is
wrong the other way: draining a backlog moves it hundreds of ms at once,
past the deadlines of the gaps the backlog shows (11-28 requests per run
against base's 0 under injected 300 ms receiver stalls).

The failure seen in a full workspace run on devbox1 was the host itself:
at load ~590 its sender went silent for 348 ms and 605 ms with frames
waiting for repairs, and the fake iPad asked for two keyframes, as the
assembler specifies once the 100 ms stall allowance is spent. Each
silence of the PC longer than that allowance while an incomplete frame
waits may now cost one request; without one the bound stays one. A slow
encoder's quiet gaps between whole frames do not count.
On a starved machine libx265 stayed silent past the supervisor's 3 s
encoder watchdog, the pipeline restarted, and the restarted stream
numbered its pictures from 1 again: "HEVC counters must advance: [39, 1]"
on mainpc, reproduced here with ETERNAL_FAULT_ENCODER_AFTER. Counters
must now rise within each epoch, and every epoch after the handoff must
start with an HEVC IRAP carrying parameter sets and the keyframe flag,
which the test did not check for a restarted stream before. The
reassembler's 100 ms expiry runs on the stream's capture clock, like the
pairing and preferred-FPS tests, and the 30 s wait is a 120 s backstop:
at load ~545 libx265 took 9 s for its first picture and made 18 in 30 s.
The recovery gap started at the first 150 ms read timeout after 30
decoded frames. The fault fires at encoder frame 45, so on a machine
slow enough to pause 150 ms between frames the gap also counted the
15 frames streamed before the crash. It now runs from the first epoch's
last datagram to the second epoch's first, the freeze a user sees, and
the 5 s bound is unchanged. The reassembler's 100 ms expiry runs on the
stream's capture clock.
The test waited 300 ms for a silent site and required the answer within
450 ms. It now waits 1 s and requires it within 1.5 s: still at the
deadline rather than at a later limit (the 3 s FAILURE_CHECK, ureq's
10 s connect timeout) or after a second wait as long as the first, with
500 ms instead of 150 ms for the return to be scheduled.
Lossy: a host silence is excused only while the encoder also stood still
with no finished frames waiting for the sender, and silences add up per
waiting frame the way the iPad's stall allowance does. At most three such
stall episodes are excused in a run.

HEVC: at most one restart, the encoder watchdog's, may start a second
epoch, and the last epoch alone must decode the frames.
@whoisaldo whoisaldo added the 0.3.4 Part of the 0.3.4 release label Oct 29, 2026
@whoisaldo whoisaldo mentioned this pull request Oct 29, 2026
@whoisaldo whoisaldo changed the title Harden four tests that failed on loaded machines Harden six tests that failed on loaded machines Oct 29, 2026
@whoisaldo
whoisaldo marked this pull request as ready for review October 30, 2026 01:37
@whoisaldo
whoisaldo merged commit 5438f9a into release/0.3.4-candidate Oct 30, 2026
11 of 12 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

0.3.4 Part of the 0.3.4 release

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants