Fix: drain the host-log writer before scene tests read captured spans - #2118
Merged
Merged
Conversation
A `[STRACE]` record reaches captured stderr through the process writer thread since hw-native-sys#2029, so a bare `capfd.readouterr()` races it and can return before the last records are written. The failure then reads as a missing span rather than a timing problem: `native_run_lifecycle` asserted `4 == 5` in CI with the captured tail showing the fifth invocation's spans still arriving. hw-native-sys#2029 fixed this shape in `runtime_fatal_codes` and `host_build_graph_validation` and missed three files that read spans the same way — `native_run_lifecycle`, `concurrent_prepare_stress` and `task_timing_slots`. All three are fixed here rather than only the one CI happened to catch, since the mechanism is identical and a drain cannot make a passing test fail. `drain_host_log` is a `tests/st/conftest.py` fixture rather than a fourth private copy of the poll loop. The wait is bounded but it is not the verdict: producers are quiescent by the time a test reads, so `pending_record_count` reaching zero is a real drain rather than a deadline standing in for correctness, and the caller's own assertion still decides. Exhausting the bound means the writer is stuck, and the message reports the drop counter so a queue loss is not read as a slow drain. The clearing reads in `concurrent_prepare_stress` drain too. Discarding an undrained buffer leaves the previous arm's tail to be written afterwards, where it lands in the next arm's verdict. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Warning Review limit reachedNext included review available in 7 minutes. View limit detailsLimit details: You’ve used the included review currently available. You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Team Run ID: 📒 Files selected for processing (4)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
CI caught this on an unrelated PR (#2117, docs-only):
native_run_lifecycleasserted4 == 5, with the captured-stderr tail showing the fifth invocation's spans still arriving.Four invocations parsed (inv 3–6); inv 7's
chip.runhad not been written yet.Since #2029 a
[STRACE]record reaches captured stderr through the process writer thread, socapfd.readouterr()races it. The failure reads as a missing span rather than a timing problem, which is what makes it expensive.Three files, not one
#2029 fixed this shape in
runtime_fatal_codesandhost_build_graph_validation. Three files read spans the same way and were missed:native_run_lifecycleconcurrent_prepare_stresstask_timing_slotsAll are fixed. The mechanism is identical and provable by reading, and a drain cannot make a passing test fail, so covering the class costs nothing and removes two flakes nobody has hit yet.
The clearing reads in
concurrent_prepare_stress(capfd.readouterr()with the result discarded, so only one arm's spans reach the verdict) needed it too: discarding an undrained buffer leaves the previous arm's tail to be written afterwards, straight into the next arm's count.drain_host_logA
tests/st/conftest.pyfixture rather than a fourth private copy of the poll loop.The wait is bounded but it is not the verdict — the objection I raised against
assert _flush_host_log(1000)during #2029's review applies here too. Producers are quiescent by the time a test reads (the run has completed), sopending_record_countreaching zero is a real drain rather than a deadline standing in for correctness, and the caller's own assertion still decides. Exhausting the bound means the writer is genuinely stuck, and the message reports the drop counter so a queue loss is not misread as a slow drain.runtime_fatal_codesandhost_build_graph_validationkeep their own marker-based_wait_for_host_log: different shape (poll until specific markers appear), already working, and not part of this change.Testing
I could not reproduce the CI failure locally — 12 runs of the case alone, 6 sweeps of its directory under
-n 4. The diagnosis is from the CI log plus the code path, and the fix is a drain, so the evidence that it is sufficient will come from CI.Changed tests exercised directly, which covers the edited lines better than the sweep does (both files are deselected from it):
native_run_lifecycleunderpytest -n 4task_timing_slots(all 6 tests, a2a3sim + a5sim)concurrent_prepare_stress(all 4, a2a3 hardware)Unrelated finding, recorded not fixed
One of the 6 xdist sweeps died with
Fatal Python error: Segmentation faultinspmd_sync_start_early_dispatch, native frame underworker.py:11404 _wait_run_handle. Not this change (the fixture is inert unless requested, and that case does not request it; the runtime was unmodifiedupstream/main). It did not reproduce in 20 consecutive runs of that case alone, so parallelism/load looks like part of the trigger. Logged locally; worth its own issue if anyone sees it again, since a segfault in the ordinary sim sweep will redden unrelated PRs and read as a flake.