Skip to content

Fix: drain the host-log writer before scene tests read captured spans - #2118

Merged
ChaoWao merged 1 commit into
hw-native-sys:mainfrom
ChaoWao:flush-before-reading-spans
Sep 3, 2026
Merged

Fix: drain the host-log writer before scene tests read captured spans#2118
ChaoWao merged 1 commit into
hw-native-sys:mainfrom
ChaoWao:flush-before-reading-spans

Conversation

@ChaoWao

@ChaoWao ChaoWao commented Sep 3, 2026

Copy link
Copy Markdown
Collaborator

Summary

CI caught this on an unrelated PR (#2117, docs-only): native_run_lifecycle asserted 4 == 5, with the captured-stderr tail showing the fifth invocation's spans still arriving.

tests/st/a2a3/host_build_graph/native_run_lifecycle/test_native_run_lifecycle.py:79: AssertionError
E       assert 4 == 5
...
Captured stderr call
[STRACE] v=1 pid=7155 tid=7155 inv=7 hid=0 depth=1 name=chip.run.runner_run ...
[STRACE] v=1 pid=7155 tid=7155 inv=7 hid=0 depth=1 name=chip.run.validate ...

Four invocations parsed (inv 3–6); inv 7's chip.run had not been written yet.

Since #2029 a [STRACE] record reaches captured stderr through the process writer thread, so capfd.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_codes and host_build_graph_validation. Three files read spans the same way and were missed:

file sites
native_run_lifecycle 1 (the one CI caught)
concurrent_prepare_stress 6 — 3 clearing, 3 counting
task_timing_slots 6

All 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_log

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 — 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), 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 genuinely stuck, and the message reports the drop counter so a queue loss is not misread as a slow drain.

runtime_fatal_codes and host_build_graph_validation keep 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_lifecycle under pytest -n 4 6/6
task_timing_slots (all 6 tests, a2a3sim + a5sim) pass
concurrent_prepare_stress (all 4, a2a3 hardware) pass
st a2a3sim / a5sim sweep 33 / 29
st a2a3 onboard sweep 67
ruff, ruff format, pyright clean

Unrelated finding, recorded not fixed

One of the 6 xdist sweeps died with Fatal Python error: Segmentation fault in spmd_sync_start_early_dispatch, native frame under worker.py:11404 _wait_run_handle. Not this change (the fixture is inert unless requested, and that case does not request it; the runtime was unmodified upstream/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.

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>
@coderabbitai

coderabbitai Bot commented Sep 3, 2026

Copy link
Copy Markdown

Warning

Review limit reached

Next included review available in 7 minutes.

Check out review usage here.

View limit details

Limit 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.

Learn how review limits work.

Review configuration:

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Team

Run ID: 04b9da3b-951e-48b4-a27a-121e9b36ec79

📥 Commits

Reviewing files that changed from the base of the PR and between 0edd65c and e323764.

📒 Files selected for processing (4)
  • tests/st/a2a3/host_build_graph/concurrent_prepare_stress/test_concurrent_prepare_stress.py
  • tests/st/a2a3/host_build_graph/native_run_lifecycle/test_native_run_lifecycle.py
  • tests/st/conftest.py
  • tests/st/task_timing/task_timing_slots/test_task_timing_e2e.py

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.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@ChaoWao
ChaoWao merged commit 14e173e into hw-native-sys:main Sep 3, 2026
18 checks passed
@ChaoWao
ChaoWao deleted the flush-before-reading-spans branch September 3, 2026 11:28
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