Skip to content

fix(cairn tests): name the I/O stall, so a 5s fsync stops reading as a code failure - #1244

Merged
ZacxDev merged 1 commit into
mainfrom
fix/cairn-write-io-stall-mechanism
Sep 3, 2026
Merged

fix(cairn tests): name the I/O stall, so a 5s fsync stops reading as a code failure#1244
ZacxDev merged 1 commit into
mainfrom
fix/cairn-write-io-stall-mechanism

Conversation

@ZacxDev

@ZacxDev ZacxDev commented Sep 2, 2026

Copy link
Copy Markdown
Member

The failure

tekton/devrc-pytests fails on test_cairn_write.py::TestAppendLands::test_a_bullet_is_appended_and_the_status_is_named on PRs whose diff cannot reach it:

AssertionError: 🔴 cairn: the write did NOT happen — http://127.0.0.1:PORT unreachable: timed out
                Nothing was queued and nothing was written locally.
assert 7 == 0

That is a sentence about the write client describing what was a disk stall.

The mechanism — read off the CI log, not inferred by analogy

🔴 The store-api root cause was NOT assumed to transfer. test_cairn_write.py imports http.server, stands up its own loopback servers, imports no store-api server.py, and carried no MECHANISM classifier — all verified first.

Established from devrc-ci-jfg67 directly:

  • the store root is /tmp/nix-build-devrc-pytests.drv-0/pytest-of-nixbld1/pytest-0/popen-gw1/… — the step container's ephemeral layer, the same device the store-api half stalls on;
  • the client reports timed out, not a refused connection;
  • server.py:_replace_bytes fsyncs the file and then the parent directory INSIDE the request, before the response is written;
  • run_cairn passes --timeout 5.

So one fsync slower than five seconds is a refusal at exit 7. 🔴 That bound is twelve times tighter than the store-api half's HANG_TIMEOUT of 60.0, which is why this file is the more frequent casualty of the same node contention.

All 5 failures in that run were exactly the 5 write-success assertions — 4× TestAppendLands plus test_put_derives_the_revision_from_a_LIVE_sync_and_the_replace_lands (--dist loadfile puts the file on one worker). Those are precisely the 5 sites this PR instruments.

What this changes: the message, and nothing else

🔴 DIAGNOSIS, NOT TOLERANCE. No bound moved, nothing retries, no test was made to pass. A gate that reports a code failure for an I/O stall trains everyone to click through — that was the whole cost.

  • scripts/testlib/hang_mechanism.py (new) — a MECHANISM = verdict from the live thread stacks, the shape test_subsystem_store_api.py already had. The failure now reads:
    MECHANISM = SERVER_BLOCKED_IN_FSYNC   (handler threads=2 [...=BLOCKED_ELSEWHERE
    ...=SERVER_BLOCKED_IN_FSYNC], accept loop parked=True)
    store=/dev/shm/devrc-store-… fs=tmpfs
    
  • 🔴 The headline is deliberately NOT a consensus of the handler threads. Two servers are live here — the store and the shim in front of it — so on a timeout they legitimately disagree (shim in urlopen, store in fsync). Measured, not anticipated. A rule requiring agreement would answer AMBIGUOUS for the textbook case the classifier exists to name.
  • 🔴 It scans frames' SOURCE LINES, never their FILENAME — the defect _HUNG_SERVER_RULES carries as known-and-unfixed, where a worktree named devrc-fsync misclassifies every hang. test_subsystem_store_api.py was not rewired onto the shared module: it has its own tests and that is its own edit. Two copies exist today; that is known debt, not an oversight.
  • scripts/ci-repro/slow_cairn_fsync.py (new) — stalls os.fsync in the test process. Not LD_PRELOAD: the server is in-process while the client is a subprocess, so preloading would stall both sides and muddy which one timed out.

Evidence

Reproduced on the dev host, text identical to CI:

run result
control (inert) 4 passed in 3.69s, intercepted_fsyncs=8
armed SLOW_CAIRN_FSYNC_S=8 4 failed in 28.95s

intercepted_fsyncs=8 is the positive control — the append path really does issue the two _replace_bytes fsyncs per write; a zero would mean the shim patched nothing. Both selftest arms watched to fire (inert-run abort; zero-fsync abort on a 2 passed selection).

The store was on tmpfs for BOTH runs (/dev/shm/devrc-store-…), i.e. with store_siting's mitigation fully in force. This is a LATENCY dependency, not a filesystem one. tmpfs makes a breach far less likely; it does not remove the 5 s bound.

Mutation matrix on the new classifier — every mutant killed, each by the right test

mutant killed by
filename folded back into the scanned text path test, with its own message
fsync rule removed from RULES 5 tests
consensus rule (disagreement ⇒ no verdict) headline test
classify always answers fsync 3 tests, incl. the pull-apart
outermost frame wins innermost test

Run under PYTHONDONTWRITEBYTECODE=1; file restored byte-identical to its pre-mutation backup afterwards.

What is NOT fixed here, and is not claimed

Gate

Verdicts in the PR comments below (dev-host tier + both nix check derivations, built one at a time).

…a code failure

`tekton/devrc-pytests` fails on `test_cairn_write.py::TestAppendLands::
test_a_bullet_is_appended_and_the_status_is_named` on PRs whose diff cannot reach
it. The gate prints

    AssertionError: 🔴 cairn: the write did NOT happen — ... unreachable: timed out
    assert 7 == 0

which is a sentence about the write CLIENT describing what was a disk stall.

MECHANISM, read off the CI log rather than inferred by analogy. On `devrc-ci-jfg67`
the store root is `/tmp/nix-build-devrc-pytests.drv-0/…/popen-gw1/…` — the step
container's ephemeral layer — and the client reports `timed out`, not a refused
connection. `server.py:_replace_bytes` fsyncs the file and then the parent directory
INSIDE the request, before the response is written; `run_cairn` passes `--timeout 5`;
so one fsync slower than five seconds is a refusal at exit 7. That bound is TWELVE
TIMES tighter than the store-api half's `HANG_TIMEOUT` of 60.0, which is why this
file is the more frequent casualty of the same node contention.

🔴 The store-api root cause was NOT assumed to transfer. `test_cairn_write.py`
imports `http.server` and stands up its own loopback servers, imports no store-api
`server.py`, and carried no `MECHANISM` classifier — all verified before relying on
any of it.

WHAT THIS CHANGES: the message, and nothing else.

* `scripts/testlib/hang_mechanism.py` (new) — a `MECHANISM =` verdict from the live
  thread stacks, the shape `test_subsystem_store_api.py` already had. Under the
  reproduction the failure now reads `MECHANISM = SERVER_BLOCKED_IN_FSYNC (handler
  threads=2 [...=BLOCKED_ELSEWHERE ...=SERVER_BLOCKED_IN_FSYNC], accept loop
  parked=True)` plus the store's filesystem.
* 🔴 DIAGNOSIS, NOT TOLERANCE. No bound moved, nothing retries, no test was made to
  pass. A gate that reports a code failure for an I/O stall trains everyone to click
  through, and that was the whole cost.
* 🔴 The headline is deliberately NOT a consensus of the handler threads. Two servers
  are live here — the store and the shim in front of it — so on a timeout they
  legitimately disagree (shim in `urlopen`, store in `fsync`). Measured. A rule
  requiring agreement would answer AMBIGUOUS for the textbook case.
* 🔴 It scans frames' SOURCE LINES, never their FILENAME — the known, unfixed defect
  `_HUNG_SERVER_RULES` carries, where a worktree named `devrc-fsync` misclassifies
  every hang. `test_subsystem_store_api.py` was NOT rewired onto the shared module;
  it has its own tests and that is its own edit. Two copies today, known debt.
* `scripts/ci-repro/slow_cairn_fsync.py` (new) — stalls `os.fsync` in the test
  process. Not `LD_PRELOAD`: the server is in-process while the client is a
  subprocess, so preloading would stall both sides and muddy which timed out.

MEASURED on `origin/main` at 946a51f, store on tmpfs for BOTH runs (i.e. with
`store_siting`'s mitigation fully in force — this is a LATENCY dependency, not a
filesystem one):

  control (inert)                 4 passed in 3.69s, intercepted_fsyncs=8
  armed SLOW_CAIRN_FSYNC_S=8      4 failed in 28.95s, text identical to CI

`intercepted_fsyncs=8` is the positive control: the append path really does issue the
two `_replace_bytes` fsyncs per write. Both selftest arms watched to fire (inert-run
abort; zero-fsync abort on a `2 passed` selection).

Mutation matrix on the new classifier — every mutant killed, each by the right test:

  filename folded back into the scanned text  -> path test, with its own message
  `fsync` rule removed from RULES             -> 5 tests
  consensus rule (disagreement => no verdict) -> headline test
  classify always answers fsync               -> 3 tests, incl. the pull-apart
  outermost frame wins                        -> innermost test

NOT FIXED HERE, and neither is claimed: the stall itself is node-local device
contention, whose levers are infra and ranked in the ci-repro README. The disk-siting
half was already fixed by b4fde33 (#1219). ⚠ A PR branched before that commit still
carries the old disk-backed fixture — branch protection sets `strict: false` and
never rebases — which is why #1209 and #1233 were still failing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session-Id: 90310ba1-6dc2-4779-a616-2ccfe89457d7
@ZacxDev

ZacxDev commented Sep 2, 2026

Copy link
Copy Markdown
Member Author

Gate verdicts

Rebased onto 5a82aaa9 (current main) before these runs, so the PR is not gated on a stale tree.

Sandbox tier — the two nix check derivations, built one at a time

derivation verdict
.#checks.x86_64-linux.nodetests RESULT: PASS (exit=0)TOTAL suites=5 files=41 tests=1449 pass=1449 fail=0 skipped=0 (floor: 1367), output path /nix/store/9qdvf84s3nczap7cy2ma4s6zklf8bp11-devrc-nodetests valid
.#checks.x86_64-linux.pytests RESULT: FAIL (exit=1)1 failure, and it is PRE-EXISTING ON main (below)

🔴 The one pytests failure is not this PR, and that is proved, not asserted.

scripts/collector/keylog/tests/test_espanso_detect.py::test_live_existing_resolutions_not_made_ambiguous
AssertionError: search terms regressed:
  {'recom': (':rna', None, [':acq', ':rna']), 'recommend': (':rna', None, [':acq', ':rna'])}

Cause: a720d30d ("espanso"), one of the five commits already on main, changed the :acq
snippet's label from "ask clarifying questions" to
"ask clarifying questions and recommend improvements and anything useful to include". The word
"recommend" now makes recom/recommend match :acq as well as :rna, so _attribute
returns None and the pinned resolution regresses.

Discriminating control — the file that decides it is byte-identical between this branch and
origin/main
(git diff origin/main -- nix/home.nix is empty), and reverting only that file
flips the result:

nix/home.nix from result
a720d30d^ 1 passed
a720d30d (= current main = this branch) 1 failed

So origin/main is red on the sandbox pytests tier right now, independently of this PR. This
diff touches no espanso config and cannot reach that test. Fixing it is a judgement call I
deliberately did not guess at
— either the new :acq label is intended and the pinned
recom -> :rna resolution needs updating, or the label should not carry "recommend". That is the
config owner's call.

Dev-host tier — scripts/gate.sh --tier both

Run before the rebase (base 946a51f0):

tier verdict
node RESULT: PASS (exit=0)tests=1449 pass=1449 fail=0
pytest RESULT: FAIL (exit=1)1 failed, 11502 passed in 612.89s; TOTAL collected=20500 passed=20496 skipped=3 failed=1

That single failure was test_git_repo_isolation.py::test_live_cotenants_sees_another_process_in_the_repo:

assert live_cotenants([git_dir]) == [], "a brand-new tmp repo already has tenants?"
AssertionError: assert ['522745:git'] == []

A stray git process was inside a brand-new tmp repo. The same log records a concurrent session
pushing another branch during the run
(refs/heads/feat/handoff-search-index-p1
926b82ce -> 0906bbb6), which is where that process came from — this box runs parallel agents.
Re-run of the whole file: 114 passed. Transient, and this diff cannot reach live_cotenants.

Change-specific verification

  • test_cairn_write.py + test_hang_mechanism.py + test_store_siting_ledger.py: 46 passed.
  • Mutation sweep on the new classifier: 5 mutants, 5 killed, each by the intended test, run under
    PYTHONDONTWRITEBYTECODE=1; module restored byte-identical to its pre-mutation backup.
  • Reproduction instrument validated in both directions, with both selftest arms watched to fire.

Honest scope: I do not have a fully green sandbox pytests verdict for this tree, because
main itself is red. What I have is that the tier's only failure is attributed, reproduced, and
flipped by reverting a file this PR does not touch.

@ZacxDev
ZacxDev merged commit 1b769b6 into main Sep 3, 2026
1 of 2 checks passed
@ZacxDev
ZacxDev deleted the fix/cairn-write-io-stall-mechanism branch September 3, 2026 21:35
ZacxDev added a commit that referenced this pull request Sep 3, 2026
… governs

Round-1 audit of #1256: one blocking, two should-fix, two nits. All fixed.
Every one is the same shape the doc exists to name -- the re-measurement was
swept through the prose and NOT through the machinery it governs.

BLOCKING -- (a) said "require a1 + a4 only" while the check 18 lines below
still read "met only when a1, a2, a3 AND a4", and the tie-breaker pointed at
the stale half ("count the # (aN) lines; they are the authority" -- there were
still four).

  Two wrong outcomes were reachable, and the sharper one is live:
  a3 `grep -c cairn` reads 7 on origin/main TODAY, because #1244 landed cairn
  content -- nothing to do with the mitigation note. So a reader following the
  formal definition scores a3 GREEN for an unrelated reason: certify-by-naming-
  one, the exact bug the item spends three paragraphs warning about.
  The other outcome: adding the words `scoped_store`/`cairn` to the README to
  force a2/a3 non-zero, committing a FALSE statement -- both are sited now.

  a2/a3 are commented out of the block (with the spurious-a3 measurement
  recorded in place), the conjunction is a1 AND a4, and the authority pointer
  now says LIVE (aN) lines. Verified: 2 live (aN) lines remain, matching "TWO
  greps, not four".

SHOULD-FIX -- a4 still described "the 13 unfixtured sites" and its regex still
carried the dead anchor `11755`, in a PR whose own headline is that the
population is 25 and whose bold warning is "the 25 are not the 13". Re-measured
2026-09-03, :11755/:11852/:12584 are now a docstring, a comment, and a
running(scoped_store, ...) block -- i.e. the citation-into-the-wrong-function
bug, reintroduced. Regex is now `unfixtured` alone; the anchors are replaced
with an instruction to DERIVE them, because line numbers in a file under active
edit are not durable.

SHOULD-FIX -- rank 5 says the tool books 10 blocks of which two are full live
content. Measured at this head: ELEVEN (11,302 B). This PR's own CLOSED block
is a third full-content H3 that handoff-audit.py buckets on its heading alone
-- and it is the one carrying the live measurement rank 13's remaining work
depends on. So the PR grew the hazard rank 5 quantifies while leaving the
quantification stale. Now says three.

NIT -- an unterminated `**` made rank 10's new SUPERSEDED banner render
literally while the older banner it supersedes rendered bold, on an OPEN LOCKED
item whose point is routing the reader to the right premise. Markers now
balanced (8).

NIT -- "3 hits each" for the cairn suites: measured 5 and 3.

Verification
- 508 passed: test_handoff_doc.py + test_doc_path_rot.py + test_skill_tiers.py.
- a3=7 re-derived by hand before accepting the finding; a1/a2/a4 all 0.
- ** balance and live-(aN) count both re-checked after the edit.
- Branch was 6 behind and is merged forward (39810a7), so the gate now runs on
  the MERGED tree rather than the branch.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session-Id: 49119183-3a2e-4274-b06b-1c29dc2288ac
ZacxDev added a commit that referenced this pull request Sep 3, 2026
…s, an untracked doc rescued, an (#1264)

Claude-Session-Id: 90310ba1-6dc2-4779-a616-2ccfe89457d7
ZacxDev added a commit that referenced this pull request Sep 4, 2026
…is doc

First full audit of #1256 (round 1 never ran — I opened this PR, its gate went
red, and I diverted to the espanso work). Two blocking, five should-fix, four
nits. Both blocking findings were caused by commits THIS PR'S OWN forward-merges
brought in, after the last content commit was written.

🔴 F1 -- the README premise is refuted, and the surviving check now directs a
   WRONG edit.

  The doc said scripts/ci-repro/README.md "carries no mitigation note (zero hits
  for tmpfs|1211|mitigat|shm)". It carries FOUR, added by #1244 (1b769b6,
  2026-09-03T21:35Z) -- which entered this branch at merge 39810a7, twelve
  minutes BEFORE the commit that revised this very block.

  The note names b4fde33 (#1219), the CORRECT consolidated fix. So a1 is not
  merely satisfied -- acting on it is now harmful: the Next probe would add the
  SUPERSEDED one-of-three 1a4350f alongside it, leaving the README asserting two
  shas as "the" siting fix with the partial one added last. That is the
  certify-by-resemblance defect this arc exists to correct, executed by following
  this doc. a1 RETIRED; a4 (the unfixtured residue, genuinely absent from the
  README) is the whole of the remaining condition.

🔴 F2 -- I deleted the test this doc's verification procedure depends on, in a
   different PR, this session.

  "How to verify" ran test_live_existing_resolutions_not_made_ambiguous against
  origin/main as the GREEN arm of the two-arm stale-base control. #1265
  (68d10b1) deleted all ten espanso live-config guards. Run as written it now
  prints "60 deselected in 0.05s" and EXITS 5 -- under -q there is no passed and
  no failed, so a reader scanning for failures reads "green on main" and
  concludes STALE BASE for any red branch, including one red for a real defect.

  That is this doc's own "a reassuring zero is indistinguishable from a probe
  wired to nothing", inside its own verification block, caused by citing the
  moving ref origin/main in the one place the section says every command must
  cite a sha.

  Fixed by restating the TECHNIQUE (which is the durable output) separately from
  the example, pinning BOTH arms of the worked example to fixed shas (f85b744
  red / c2daa65 green), and requiring a passed/failed COUNT rather than an exit
  code, because -k matching nothing exits 5 and reads as success.

Also fixed
- F3 the headline AST figures were attributed to origin/main, a moving ref, in
  the same bullet that says every figure is sha-stamped. Now pinned to b4fde33,
  with the drift stated (288/136/127/25 at a7dac5b, via #1254) AND the one
  figure any decision rests on called out as sha-INDEPENDENT: the 25 unfixtured
  sites are still exactly 25, all tmp_path-rooted, 0 sited, re-verified per-site
  at current main by the auditor.
- F4 the a3 note said #1244's cairn content had "nothing to do with the
  mitigation note". All 7 hits are in the SAME contiguous block that carries the
  mitigation sentences. Reading one grep and declaring the neighbours irrelevant
  is what stopped anyone looking, and is why F1 survived a revision pass.
- F5 the closing condition's designated arbiter ("count the LIVE # (aN) lines")
  yields THREE, not two -- "live" is not a property a count can see. Arbiter
  removed in favour of the sentence naming the required checks.
- F6 one sentence said the README returns 0 for `cairn` while another 137 lines
  below said 7. Corrected. The fsync control's "= 25" is now stated as non-zero
  (25 at b4fde33, 32 at a7dac5b).
- F7 the cairn store_siting counts: at b4fde33 it is 3 and 3, so the earlier
  "3 each" draft this block corrected was RIGHT; 5 is true only at a7dac5b,
  where #1244 added two PROSE mentions that are not siting sites. Each file has
  exactly one store_root() call.

Verification
- 490 passed: test_handoff_doc.py + test_handoff_audit.py + test_doc_path_rot.py.
- Both blocking findings re-derived by hand before acting: the README's 4 hits
  and the b4fde33 mention read off origin/main; the deleted test confirmed
  absent from origin/main.
- Forward-merged main first (19 behind, no conflict, doc untouched by all 19),
  which is what made the inherited-red theory testable: the failing test was
  present on the branch before the merge and gone after.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session-Id: 49119183-3a2e-4274-b06b-1c29dc2288ac
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