Observation record: watch #67 failed once each on three unrelated PRs in one night, and not on main

[fujibee]

Three sightings in one night, on three pull requests that touch three different files, and zero on
main in the same window. Recording them together so there is a count rather than three separate
recollections. This is not a flakiness claim — it is the opposite: the observations are being
written down precisely so that whether it is a flake stays an open question with evidence attached.

tests/test_watch.bats:208
  watch: exits when its session dies without consuming an undelivered row (#67)

PR	what that PR changes	leg
#970	scripts/lib/instance-id.sh — the liveness helper	bats (macos-latest 1/4)
#991	scripts/watch.sh and friends — argv-to-stdin	bats (macos-latest 3/4)
#904	scripts/lib/storage.sh, the sqlite drivers — probe placement	bats (ubuntu-latest 4/4)

On main: checking every failing main run in the last twelve
(gh run list --workflow tests.yml --branch main, then --log-failed | grep "(#67)"), this test
does not appear once. The failures present there are the two #937 launcher tests and the
pair-release test now correctly naming #983.

Why the three are worth one record

Each author reasonably concluded it was not theirs, and each was reasoning correctly in isolation:

• fix(storage): probe before the pipe, not inside it (#462) #904's author took a second sample (green), ran the test three times locally (3/3 green), and
  noted the failure lands in _wait_for_file_contains's ten-second window rather than in the
  behaviour under test.
• fix(instance-id): distinguish a failed ps observation from proof of death (#954) #970's author established that the lines that PR changes are not on the path this test takes —
  it reaches agmsg_instance_alive through the composite-id branch, not the bare-id one.

Both are sound. What none of them could see alone is that the test also failed for two other people,
on two other platforms, for two other changes, on the same night.

What is and is not established

Established: the test failed once each on three unrelated branches, and not on main in that
window; it is not confined to one platform; and at least one failure is inside a bounded wait rather
than an assertion about watcher behaviour.

Not established: whether these are one phenomenon or three, whether the bounded wait is the
mechanism or just where the symptom surfaces, and whether the rate on main is genuinely zero or
merely below the number of runs looked at.

What would settle it

• The observed state at the timeout, not just that the wait expired. _wait_for_file_contains
  gives up after 100 × 0.1s; what the file contained at that moment is the difference between "the
  watcher never exited" and "the watcher exited but the line had not been written yet".
• A fourth sighting with its leg and OS, added here, so the rate becomes a rate.
• Whether the test's notion of "the session died" depends on ps/pid visibility. It embeds a
  controllable stand-in session pid in a composite instance id and kills it, so it may share a root
  with Six open items reduce to one question: positive evidence that a process is gone #996 — but that is a hypothesis, not a finding.

A note on how these were nearly lost

Two of the three were found on runs that were subsequently re-run to green. The re-runs were
legitimate — in both cases the failing test was identified and its identity recorded before the
re-run — but the record lived in chat. Re-running to green erases the frequency unless the
observation lands somewhere countable first. This issue is that somewhere.

[fujibee]

Another occurrence, recorded before any rerun.

run          33346168106 (tests.yml, attempt 1)
head         9363be656b5bad1093841aa4434df5c5f62080cf
shard        bats (macos-latest 4/4)
failure      not ok 336 watch: a pair claimed by another session is released, not consumed (#983)

The diff on that head is +1109/-0 across eight files, all of them newly added (scripts/drivers/terminals/*, scripts/lib/terminal-registry.sh, tests/test_terminal_registry.bats). No existing file is modified, so nothing in it reaches watch.sh or the pair-claim path.

That makes this the same shape this issue records: a watch test falling on a PR that cannot have caused it. Adding the data point rather than rerunning.

[fujibee]

Correcting the earlier comment on this issue.

That comment argued the occurrence on 9363be6 could not have been caused by the branch, because the diff was +1109/-0 across eight newly added files and reached nothing the test uses. That was accurate for that head. It is no longer accurate for the branch's current head, and the same test has now failed on it again — this time on ubuntu-latest 2/4 rather than macOS.

run     33477264715 (tests.yml, attempt 1)
head    6d9a6a351b66c579270d3af17923814c2150a373
shard   bats (ubuntu-latest 2/4)
failure not ok 341 watch: a pair claimed by another session is released, not consumed (#983)

The branch has since grown to 28 files and now modifies existing scripts, scripts/join.sh among them. The failing test reaches it:

tests/test_actas_integration.bats:31
  fake_register() { bash "$SKILL_DIR/scripts/join.sh" "$team" "$agent" claude-code "$proj"; }

tests/test_actas_integration.bats:205
  fake_register T alice
  fake_register T bob

So the "cannot have caused it" reasoning no longer applies, and this occurrence is not evidence for the flake being independent of the change. It is being reproduced and root-caused on the branch rather than rerun; whichever way that lands will be recorded here.

Two things worth separating for anyone reading the count on this issue: the occurrences recorded before the branch modified existing scripts still stand as independent data points. This one does not, and should not be counted with them.

[fujibee]

This issue's title says the failure happened on three PRs and not on main. That premise no longer holds, measured on CI rather than locally.

CI history on main

The last 30 tests.yml runs on main contain 12 failures. Reading --log-failed for each of those 12 and counting not ok ... #983:

33360811033  head c1b52f8   macos-latest 4/4    not ok 321   (ok lines: 431)
32944981464  head 0d08381b  macos-latest 2/4    not ok 319   (ok lines: 844)
32820222766  head debffbe7  ubuntu-latest 2/4   present      (ok lines: 840)

The remaining nine are zero — with one qualification that matters: two of those nine returned only 0 and 2 ok lines respectively, meaning the bats output itself did not come back. Those two are "could not read", not "absent", and are not counted as evidence either way. The ok line count is carried here as a canary for exactly that: a log that answered has hundreds of them.

32820222766 is on ubuntu-latest 2/4 — the same OS and the same shard as the branch failure recorded earlier in this thread.

Local repetition, both trees

Running tests/test_actas_integration.bats on its own, four times per tree:

main c1b52f8   2 of 4 runs failed   the failures were #11 (the same test CI hit) and #8
branch head    2 of 4 runs failed   the failures were #10 and #12

Same rate, and a different test each time. On this machine the file is unstable as a group; nothing here says the branch changes the rate.

What this means for the earlier comments

The comment arguing an occurrence "cannot have been caused by the branch" and the later one withdrawing that argument were both about which head was in play. Neither settles the question, and both were written before there was CI evidence about main. This is the observation that settles it: the same test fails on main in CI, including on the same shard.

So the three-PRs-and-not-main framing in the title should not be used as evidence that the failure tracks a change. Retitling or reframing this issue around "unstable as a group, on main too" would describe what has now been measured.

[fujibee]

Closing out the question this thread kept re-opening: does the failure rate of this test track a particular branch? Measured two ways, and the answer is no.

Controlled: the same test, both trees, interleaved

Running only this test (bats -f "released, not consumed") on one machine:

sequential   main x20 first, then branch x20     main 0/20   branch 6/20
interleaved  one main, one branch, alternating   main 3/25   branch 3/25

The only difference between those two runs is the order. This test depends on process liveness within a fixed sleep budget, so a tree measured on a quiet machine and a tree measured after twenty prior runs are not measured under the same conditions. The sequential numbers are a load confound and should not be used; they are recorded here only because they are exactly the shape that would otherwise look like strong evidence of a regression.

Interleaved, with 25 runs per tree, the rate is the same.

Observational: CI run outcomes

The CI record initially looked different — on one feature branch, 3 of the 5 runs that reached a conclusion failed with this test, against 3 in 30 on main. That comparison does not hold up. Of that branch's 31 runs, 26 were cancelled by a superseding push, and the cancelled set is not a random sample: cancellation timing correlates with how far the run had progressed, so which runs survive to a conclusion is not independent of the outcome. The denominator was measured (31/31 runs' job data retrieved, with a positive control that per-job data comes back at all before counting), and it is biased.

So the interleaved measurement is the one that answers the question, and it finds no branch effect.

What this issue is actually about, then

The title's framing — three PRs and not main — is not supported. Earlier in this thread the CI record on main was shown to contain this failure too. Together with the above, what is established is:

• the test fails intermittently on main and on branches, at a similar rate
• the rate responds to machine load, which is why sequential comparisons mislead
• nothing measured so far identifies a change that causes it

Which makes this an unfixed intermittent failure in the test itself, not a signal about any particular change. Retitling around that would stop the next person from reading a branch correlation into it — three separate readings in this thread have now had to be withdrawn, including two of mine.

[fujibee]

Narrowing the previous comment. Its local, interleaved result stands; its treatment of the CI record does not.

That comment dismissed the CI comparison as unusable because of cancellation bias. Both sides have since been restored the same way — counting only runs that reached a verdict, on both branch and main:

branch   7 failures / 15 verdicts   47%     (three days, pushes stacked)
main     3 failures / 18 verdicts   17%     (spread over a wider period)

local, interleaved, this test only    main 12%   branch 12%

So there IS a comparable CI comparison, and it shows a gap of roughly 2.8x. What the interleaved local run establishes is narrower than "settled": under identical conditions the two trees behave the same, and the local 12% sits close to main's CI 17%. The branch's 47% is therefore not explained by anything measured in the trees — but it is also not explained away. It remains an open number.

The leading candidate is a condition difference rather than a content one: the branch's fifteen verdicts come from three days of stacked pushes, main's eighteen from a much longer window, and this test is load-sensitive by construction. That is a hypothesis, not a finding. It is being tested directly — per-run concurrency at the time each verdict was reached, against whether that run failed — and the result will be posted here either way.

Recording the correction rather than quietly replacing the number: the previous comment said the question was answered, and it was not.

[fujibee]

The concurrency hypothesis from the previous comment was tested and does not hold. Posting it as promised.

Method, and a trap found while checking it

Placing each run in time needs a start and end. Two sources exist, and they disagree:

run level   run_started_at -> updated_at
job level   min(started_at) -> max(completed_at)

attempt=1 runs (4 checked)   agree within 30 seconds
attempt=2 run  (1 checked)   25 minutes apart

run_started_at on a re-run is the re-run's own time, while the jobs still carry the original attempt. The single run picked first as a sanity check happened to be that attempt=2 one. Without checking, every re-run in the population would have been placed 25 minutes off.

So: attempt=1 runs are placed from the run level (verified against the job level), and attempt>1 runs are dropped as "position unknown" rather than counted at a wrong time — 1 of 34 verdict runs, plus 13 of the 347-run background population. Every concurrency figure below is therefore a lower bound.

The counter itself was controlled: adding a synthetic run spanning the whole window raises every count by exactly 1; adding one outside the window changes nothing; the raw values range 1–4 rather than being constant.

Result

branch   FAIL 6 runs, concurrency [1,2,2,2,3,3]              mean 2.2
         pass 9 runs,             [1,2,2,2,2,2,3,4,4]        mean 2.4
main     FAIL 3 runs,             [1,1,3]                    mean 1.7
         pass 15 runs,            [1,1,1,1,1,1,2,2,2,2,2,2,3,3,3]  mean 1.8

both sides pooled, failure rate by concurrency
   1 concurrent    3/10
   2 concurrent    3/14
   3+ concurrent   3/9

Within each side, failing and passing runs sat at the same concurrency. Pooled, the rate is flat. The branch does run at a higher average concurrency (2.3 vs 1.8), but there is no sign that difference produces the failures.

Scope of this refutation, kept narrow: what was measured is the number of this repository's runs overlapping in time. Actual runner contention on GitHub-hosted runners happens per job across an account, so a repo run-count is a weak proxy for it. This rules out in-repo crowding; it does not rule out load. Load is demonstrably a factor — the local sequential-vs-interleaved result (0/20 vs 6/20, becoming 3/25 vs 3/25 when interleaved) was purely a load artifact. A different proxy is needed.

Corrected figure

One further branch run reached a verdict and passed, and the completed runs were re-derived by the same restoration used for the cancelled ones rather than carried over from an earlier comment:

branch   7 / 16   44%     (3/6 completed + 4/10 cancelled-but-decided)
main     3 / 18   17%     (unchanged)

The gap is still there, and it is still unexplained.

[fujibee]

Closing this line of investigation without an answer, and saying so, so the next person does not walk it again from the start.

The runtime lead is withdrawn

An earlier measurement had the branch's shard taking 2.76x as long as main's (1099s vs 3030s) on comparable test counts, which would have been a plausible cause for a load-sensitive test failing more often. Re-running the same byte-identical 22 files on both trees to isolate scripts/ from the neighbour set produced this instead:

main   442 tests   976s     0 failures
head   same set    still running after 6h48m (19 of 22 files, progressing)

The same tree had completed nearly the same set in 3030s an hour earlier. Same tree, same files, more than 8x apart. So 2.76x is not a property of either tree, and it is withdrawn.

Why local measurement cannot settle this

That 8x is the machine, not the code. Several agent sessions share this host, and their load moves in ways the measurement does not control for. The same confound already appeared in the failure-rate numbers: running one tree's 20 iterations and then the other's gave 0/20 vs 6/20, while interleaving them gave 3/25 vs 3/25. Wall-clock and failure rate are both unreliable here unless interleaved, and interleaving does not help when a single run takes hours.

What is established, and what is not

Established:

• the test fails intermittently on main as well as on branches (CI evidence, earlier in this thread)
• under interleaved local conditions the two trees fail at the same rate
• the CI record shows a gap on comparable denominators (branch 7/16, main 3/18) that none of the tested hypotheses explains
• in-repo run concurrency does not explain it (flat failure rate across 1, 2, 3+ concurrent runs)
• the two shards are nearly disjoint (4 of 22 files shared), so the test genuinely runs beside different neighbours — but neither the static weight proxies nor position-in-shard separates them, and the runtime measurement that might have is unusable

Not established: what causes the gap.

Deliberately stopping

The remaining approach is to accumulate CI runs until the numbers separate, at 20–50 minutes per data point and no guarantee of convergence. That is not worth it for a test that is already documented as intermittent and already governed by a "record the failure before rerunning" policy.

So: unexplained, not chased further, and the reason is written down rather than left as an absence.

[fujibee]

Fourth observation, and the first on main: run 34739006782 (push to main at d354ae8, ubuntu 5/5), watch: exits when its session dies without consuming an undelivered row (#67) at tests/test_watch.bats:296. The merged commit (#1180) touches only tests/remote_sync_engine.test.mjs.

This one carries the detail the issue asked for. The failing assertion is

run kill -0 "$w"; [ "$status" -ne 0 ]

and the line before it, _wait_for_missing "$pf" || { kill "$w" ...; false; }, did not fail. So the pidfile had already been removed when kill -0 still found the process alive: the watcher's cleanup() (installed with trap cleanup EXIT) had run and deleted the pidfile, but the shell had not yet actually exited by the time the test checked. The test treats "pidfile gone" and "process gone" as the same instant; between them there is a short window, and on a loaded runner it is wide enough to land in.

Frequency: the 25 most recent main runs contain no other occurrence, and the 60 most recent runs across all branches contain none besides the three PR-branch cases this issue already lists, so there is not enough data to say whether the 5-shard layout (#1162) changed the rate.

If the intent of the test is "the watcher exits", waiting on the process (a bounded poll of kill -0) after the pidfile disappears would assert that directly rather than inferring it from the file.

[fujibee]

Fifth observation, the second on main in one day: run 34739603307 attempt 2 (push to main at 3ab9e31, macOS 5/5), same test, same line (tests/test_watch.bats:296). The merged commit (#978) touches only the codex bridge launcher, codex-bridge.js, and their test file. Attempt 1 of the same run had failed on a different job, so this red is not a re-run of an earlier failure of this test.