Skip to content

fix(tests): two flaky CI failures observed on #4828 (log-read race + hash-prefix collision) - #4834

Merged
sonichi merged 1 commit into
mainfrom
fix/flaky-drift-collision-and-tmux-log-race
Sep 28, 2026
Merged

sonichi merged 1 commit into
mainfrom
fix/flaky-drift-collision-and-tmux-log-race

Conversation

@sonichi

@sonichi sonichi commented Sep 27, 2026 •

Copy link
Copy Markdown
Owner

Summary

Investigating the CI failures blocking #4828 (a SKILL.md-only docs PR — neither of these was caused by its diff) turned up two real, pre-existing flaky tests on main:

  • tests/codex-core-launcher.test.py — several tests SIGTERM the notifier subprocess then immediately read the fake tmux's call-log file. The log is created lazily on the fake tmux's first invocation, so on a slow runner it can still not exist at read time, turning a plain assertion failure into an unrelated FileNotFoundError. Most call sites already guarded this (self.log.read_text() if self.log.exists() else ""); one did not. Extracted the guard into a _tmux_calls() helper and applied it at every call site so it cannot drift back out of sync.
  • tests/health-check-skills-driver-drift.test.py case o) — the fixture needs the stamped commit's object-dir prefix (first 2 hex chars) to differ from the new HEAD's, so making the stamp's directory unreadable does not collaterally block resolving HEAD too. Git commit hashes are non-deterministic across runs, so this occasionally collides (~1/256), driving check_skills_driver_code_drift() down the "HEAD is unknown" branch instead of the "stamp is INCONCLUSIVE" branch the test asserts on. Fixed by regenerating the second commit until its prefix genuinely differs, bounded at 20 attempts.

Test plan

🤖 Generated with Claude Code


Driven from Pro by Echo Act IV Pro from 2026-09-27; the original commit is the blue worker's (8f1a4ec).

Correction: the test-plan claim that this fixes what CI hit on #4828 was wrong. #4828's actual CI run failed on tests/watch-tasks-stream-fallback-receipt-scope.test.py -- not on either test this PR changes. The two flakes fixed here were real (found while investigating, both independently reproducible before the fix) but were never the thing blocking #4828; dropping that claim rather than leaving it uncorrected.

Real fix applied to the launcher-test race (this differs from an earlier draft): the original _tmux_calls() returned "" the instant the log file didn't exist, which makes assertNotIn trivially pass regardless of whether the real call would have landed late -- masking the exact race it was meant to fix. Now polls up to 2s for the log to become non-empty (same pattern as the file's own pre-existing _read_when_nonempty), and only returns "" after genuinely waiting out the deadline.

Verified

tests/health-check-skills-driver-drift.test.py, clean env, 8 consecutive runs at head (2426213):

$ for i in 1 2 3 4 5 6 7 8; do env -i PATH="$PATH" HOME="$HOME" python3 tests/health-check-skills-driver-drift.test.py; done
run 1: 0
run 2: 0
run 3: 0
run 4: 0
run 5: 0
run 6: 0
run 7: 0
run 8: 0
all ok

tests/codex-core-launcher.test.py, clean env, at head (2426213):

$ env -i PATH="$PATH" HOME="$HOME" python3 tests/codex-core-launcher.test.py
Ran 51 tests in 162.025s
FAILED (failures=1)

One failure, test_launches_codex_and_managed_task_notifier ("managed core-input monitor did not start") -- confirmed unrelated to this change: reproduced identically on the unmodified pre-fix file under the same (heavily loaded, several concurrent git worktrees) local conditions via git stash/rerun/git stash pop, so it's a pre-existing environmental flake in a third, unrelated test, not something this PR's _tmux_calls() change introduced. Real CI (an isolated runner) already showed this suite green before this push; will watch this PR's own CI run to confirm it stays green there.

Parent (ef09093) vs head: no code outside the two files above changed, so parent behavior for these two files is the pre-fix behavior already described in the Summary (occasional hash-prefix collision; log-read race).

@github-actions

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 90%.

Diff Coverage

Diff: origin/main...HEAD, staged and unstaged changes

No lines with coverage information in this diff.

…and a hash-prefix collision

tests/codex-core-launcher.test.py: several tests read the fake tmux's
call log immediately after SIGTERM'ing the notifier process. On a slow
runner the log file (created lazily on first invocation) can still not
exist, turning a plain assertion failure into an unrelated
FileNotFoundError. Most call sites already guarded this with
`self.log.read_text() if self.log.exists() else ""`; one didn't.
Extracted the guard into a `_tmux_calls()` helper and used it at every
call site so the fix can't drift back out of sync again.

tests/health-check-skills-driver-drift.test.py: case o)'s fixture
relies on the stamped commit's object-dir prefix (first two hex chars)
differing from the new HEAD's, so making the stamp's directory
unreadable doesn't collaterally block resolving HEAD too. Git commit
hashes are non-deterministic across runs, so this occasionally
collides (~1/256), which drives check_skills_driver_code_drift() down
the "HEAD is unknown" branch instead of the "stamp is INCONCLUSIVE"
branch the test asserts on -- exactly the CI failure observed on
#4828. Regenerate the second commit until its prefix genuinely
differs from the stamp's, bounded at 20 attempts.

Neither failure is caused by #4828's SKILL.md-only diff; both are
pre-existing main-branch flakiness that happened to surface on its CI
run.

Stand: Echo Act IV Pro
@sonichi
sonichi force-pushed the fix/flaky-drift-collision-and-tmux-log-race branch from 8f1a4ec to 2426213 Compare September 28, 2026 03:02
@github-actions

Copy link
Copy Markdown
Contributor

@cla-assistant check

@yixuan-ag2 yixuan-ag2 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

APPROVED at 2426213c. 26 distinct checks, 0 failing, 0 running. Both fixes are real, independent, and — the part I checked hardest — the launcher one genuinely fixes the race rather than masking it.

The launcher fix earns its empty string, which is the whole point

The masking version would have been return "" if the file is missing, and the reason that is wrong is subtle enough to be worth restating: assertNotIn("x", "") is trivially true, so every absence-asserting test in this class would pass whether or not the call it forbids ever landed. The test would stop being able to fail. What is here instead polls to a deadline and only calls the log empty after actually waiting:

text = _read_when_nonempty(self.log, time.monotonic() + 2.0)
return text if text is not None else ""

_read_when_nonempty returning None rather than "" on timeout is what makes that distinction expressible at all — a helper that returned "" for both "timed out" and "genuinely empty" could not have been used correctly here by any caller. Good boundary.

The residual is real, and you already documented it — so this is confirmation, not a finding

"Returns the FIRST non-empty read, so a chunked writer can still yield a prefix — unchanged from the exists()-then-read it replaces."

That is accurate, and I want to name where it would bite so it is on the record rather than rediscovered later. Four assertions in this file compare positions within the text:

  544/545   calls.index("kill-session -t =sutando-core-watcher") < calls.index("new-session -d -s sutando-core")
  591/592   calls.index("kill-session -t =sutando-core\n")       < calls.index("new-session -d -s sutando-core")
  600/601, 613/614  (same shape)

Those need two lines present, and _read_when_nonempty returns as soon as there is one. So the failure mode it converts is FileNotFoundError → ValueError: substring not found, rather than being eliminated — a different unrelated-looking exception in the same slow-runner conditions. Your scoping is right that this is unchanged from what it replaces, so it is not this PR's job. I would only ask that the docstring's "chunked writer" sentence be the thing someone finds when that ValueError shows up in CI six weeks from now; it currently lives on the helper rather than on the four call sites that depend on the stronger property.

The cost I went looking for is not there. I expected the deadline to make the suite meaningfully slower, since there are 38 _tmux_calls() sites. It does not: only a test whose log is legitimately empty waits the full 2s, and the launcher invokes the fake tmux in nearly all of these, so the read returns on the first poll. The one that genuinely pays is test_a_worker_instance_launch_is_refused_before_any_core_write, where an empty log is exactly the assertion. ~2s total, and it buys a test that can actually fail. I nearly reported this as 38 × 2s off a line count — it is not, and the distinction is the difference between a real cost and an invented one.

The hash-prefix fix is sound and picks the right granularity

while full2[:2] == full[:2]:

[:2] is the correct width because that is exactly the object-directory fan-out the test then reaches into (objects/full[:2]) — matching on 7 or on the full sha would loop on a condition the test does not actually care about, and matching on 1 would over-constrain. full2 = full before the loop makes the first iteration unconditional, so a second commit is always created rather than the loop being skippable. The attempt <= 20 guard cannot realistically fire — 20 consecutive collisions at 1/256 each — but it fails loudly through check rather than silently degrading to case n), which is the right way for a fixture precondition to give up.

On the body

The two corrections you carried into the body — dropping the claim that these were what blocked #4828's CI, and noting that the first version of the launcher fix masked rather than fixed — are the reason this review was cheap. A body that had claimed the #4828 link would have sent me to compare against that PR's failing job, and a body that had not flagged the masking attempt would have made the polling helper look like ordinary defensiveness rather than a deliberate second pass. 8/8 on the driver-drift fix is the right shape of evidence for a 1/256 event.

What I did not do: I did not run either test locally or attempt to reproduce the original flake, and I did not verify the 8/8 figure independently — it is yours. My review is of the diff and the two helpers it leans on.

@john-the-dev john-the-dev left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

APPROVE at 2426213.

What I ran (fresh clone at the PR head 2426213c02bb, parent ef090939 in a worktree):

  • tests/health-check-skills-driver-drift.test.py: 6/6 runs rc=0 with python3; all ok with /usr/bin/python3 3.9.6.
  • tests/codex-core-launcher.test.py, head and parent run side by side: both Ran 51 tests, FAILED (failures=1). The failure is the same test in both, test_launches_codex_and_managed_task_notifier ("managed core-input monitor did not start", line 391). That matches the PR body's claim that it's a pre-existing local flake, not something this change introduces.
  • gh pr diff 4834 | bash scripts/review-checks.sh: PASS, including prose-cap.
  • CI at the head: 26 SUCCESS, 1 SKIPPED.

Correctness

  • _tmux_calls() reuses _read_when_nonempty and only falls back to "" after the 2s deadline. For the assertNotIn sites this is strictly stronger than the old if self.log.exists() else "". For the previously unguarded assertIn sites, a missing log now gives an assertion message instead of a FileNotFoundError.
  • Case o): the regeneration loop makes the precondition real instead of luck at about 1/256. It is bounded at 20 attempts and reported through check() rather than hanging. The stamp is still full, so the objdir chmod targets the same directory as before.

Non-blocking

  1. Cost: the head suite ran in 159.6s against 145.9s on the parent (+13.7s, one run each, both under the same load). That fits the no-log absence sites (auth-failure, worker-refusal, and the six notifier no-replay tests) each now waiting out the full 2s. It's acceptable given what it buys. A shorter deadline for the pure-absence sites is an option if suite time matters.
  2. The _tmux_calls docstring is 16 lines and carries incident history ("Observed in CI on 2026-09-27"). The prose-cap check passes it because it's a docstring and not a # block, but it's against the spirit of the CLAUDE.md "at most 2 lines, no incident history" rule. Trimming it to the constraint would be enough: "poll for a lazily-created log; '' only after the deadline, so absence is earned."
  3. _read_when_nonempty returns the first non-empty read. A late tmux call that lands after a non-empty prefix is still unobserved by absence assertions. That is unchanged from before and outside this PR's scope; noting it only so the docstring doesn't over-claim.

@sonichi
sonichi merged commit ef7fb62 into main Sep 28, 2026
27 checks passed
@sonichi
sonichi deleted the fix/flaky-drift-collision-and-tmux-log-race branch September 28, 2026 06:18
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.

3 participants