From 3a62762a6eb6bb4292124ba95bbc302020c9df30 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Mon, 10 Aug 2026 19:54:48 +0000 Subject: [PATCH 1/2] fix(agent-role): close #296 -- a falsified TTL comment and an escapable publish pin Both were recorded as LOW by #295's final review rather than blocked. Neither changes what `agent-role.py` does; the shipped publish is unchanged. 1. `RECORD_TTL_SECONDS`' comment still said a stale record is "unlinked by the next `claim`". `keep_canonical` made that false for THIS worktree's record -- it is REPLACED, never unlinked, which is the whole point of the fix. The byte-identical sentence in the spec was corrected when that landed and the source copy, one screen above the function it describes, was missed. It now carries the same qualification, and a tree-wide search found no third copy. 2. `test_a_publish_never_leaves_the_record_NAME_absent` watched four I/O primitives, so a publish written `os.rename(target, aside)` then `open(target, "w")` escaped it. MEASURED: the pre-#296 suite is 59/59 GREEN under exactly that mutation, while a concurrent `show` in the window returns rc=3 role=UNDECLARED. That is the third consecutive round in which one publish-coverage residual was fixed and the next one opened, and the reason is structural: ANY monkeypatch-watcher pin is escapable by one more primitive, so widening the list chases a fixed point. The pin is now two tests that fail differently. `_watch_publish` (deterministic, in-process) additionally watches `os.rename`/`os.replace` and `Path.rename`/`Path.replace` as SOURCE -- the shipped `os.replace(temp, target)` has the record as DESTINATION and never removes the name -- plus `builtins.open`/`io.open`/`os.open` in write modes. `test_a_concurrent_observer_never_sees_the_record_name_absent` (probabilistic, out-of-process) republishes the record 200 times in a subprocess while the test process does nothing but poll `exists()`. It enumerates no primitive, so it is the only half that can catch one nobody listed. It is ONE-SIDED -- a hit proves absence, a miss proves nothing -- so it cannot go red on correct code however the two processes are scheduled; `os.replace` never lets the name stop resolving. Contention costs detection probability, never a red run. MEASURED 2026-08-10, 20-core box already at load average 263, ~1.5ms per publish against ~1us per poll, 150k-300k polls per run: publish under test watcher observer os.rename + open (documented escape) RED 10/10 (and 10/10 at 60) unlink + write_text (prior escape) RED 10/10 byte-at-a-time in-place rewrite green* 0/6 shipped write temp + os.replace green 40/40 green, 0 absent shipped, both processes on ONE core green 20/20 green os.rename + open, on ONE core RED 1/15 * caught instead by test_a_publish_replaces_the_record_and_never_rewrites_it_ in_place, whose hardlink witness is that mutation's subject. The two single-core rows are why BOTH halves ship rather than either. The observer needs real parallelism -- pinned to one core the publisher is rarely preempted inside a window lasting microseconds -- and is blind by construction to a publish that never makes the name absent. The watcher is unaffected by scheduling but covers only what it names. Neither subsumes the other. Sizing: 200 publishes is ~0.39s, chosen for margin over the 60 that already detected 10/10. The only non-assertion guard is a floor of 200 polls, ~0.1% of the measured count, whose sole job is to notice a poll loop that never ran. The test's stated claim was weakened to match what it proves: it no longer claims "at the instant ANY file content is written ... NOTHING may unlink it", but bounds itself to the primitives `_watch_publish` names and points at the observer for the rest. Gates: test_agent_role 60 (was 59, +1), test_agent_onboard 39, test_agent_start 20, all green; `scripts/agent-preflight.sh --quiet` green before and after (with --no-require-role: this session declared no role, so the role gate would report its own state, not the tree's). FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: Claude-Code:claude-opus-5 [Claude Code] --- .agents/roadmap_v1.md | 1 + .agents/specs/operator-record.md | 71 +++++++++ scripts/agent-role.py | 10 +- tests/scripts/test_agent_role.py | 266 ++++++++++++++++++++++++++----- 4 files changed, 308 insertions(+), 40 deletions(-) diff --git a/.agents/roadmap_v1.md b/.agents/roadmap_v1.md index 8ecbc01c8..dd7079994 100644 --- a/.agents/roadmap_v1.md +++ b/.agents/roadmap_v1.md @@ -37,6 +37,7 @@ issue is not yet placed. Keyed record: update in place, never append. | Issue | Row | Title | Kind | |---:|---|---|---| | [#287](https://github.com/mudler/vllm.cpp/issues/287) | `KV-MOONCAKE-STORE` | `MooncakeStoreConnector`: the KV store half is linkable native C++ and gateable over TCP on one box | feature | +| [#296](https://github.com/mudler/vllm.cpp/issues/296) | — | Two limitations recorded when #285 landed: a stale TTL comment, and a publish-NAME pin `os.rename` escapes (spec `specs/operator-record.md`, "Follow-up") | bug | | [#285](https://github.com/mudler/vllm.cpp/issues/285) | — | The operator lock refuses a second coordinator; it should only RECORD who is working where (spec `specs/operator-record.md`) | bug | | [#241](https://github.com/mudler/vllm.cpp/issues/241) | `ROAD-V1-H3` | MiniMax-H3: support the PRUNED (AdaLN timestep-curve) checkpoint variants | feature | | [#250](https://github.com/mudler/vllm.cpp/issues/250) | — | `a5b52047` reached main without a task branch, and `check-role-discipline` cannot be waived | bug | diff --git a/.agents/specs/operator-record.md b/.agents/specs/operator-record.md index f532305a8..b51fdd0f2 100644 --- a/.agents/specs/operator-record.md +++ b/.agents/specs/operator-record.md @@ -184,3 +184,74 @@ inode it read, so a PEER that republishes inside the window loses that record. Its remedy is `claim operator`, which is never refused. With `keep_canonical` that declination is now confined to peers; this worktree's own record is no longer exposed to it. + +## Follow-up: issue [#296](https://github.com/mudler/vllm.cpp/issues/296) + +Round 3's final review passed with two LOW findings recorded rather than +blocked. Both are closed on `row/ENG-OPERATOR-RECORD-COVERAGE`. No product +behaviour changes: `scripts/agent-role.py`'s publish is unchanged apart from one +comment. + +**1. The `RECORD_TTL_SECONDS` comment was falsified by its own fix.** It still +said a stale record is *"unlinked by the next `claim`"*, which `keep_canonical` +made untrue for THIS worktree's record — that one is replaced, never unlinked. +The identical sentence at line 74 above was corrected when the fix landed and +the source copy, one screen above the function it describes, was not. It now +carries the same qualification, and a tree-wide search found no third copy. + +**2. The publish-NAME pin was escapable, and widening it again would not have +been the fix.** `test_a_publish_never_leaves_the_record_NAME_absent` watched +`Path.write_text`, `Path.unlink`, `os.unlink` and `os.remove`. A publish written +`os.rename(target, aside)` then `open(target, "w")` escaped it: MEASURED, the +pre-#296 suite is 59/59 green under that mutation. That is the third round in a +row where one publish-coverage residual was fixed and the next one opened, and +the reason is structural — **any monkeypatch-watcher pin is escapable by one more +I/O primitive**, so widening the list chases a fixed point. + +The pin is now two tests that fail differently, and the evidence says neither +subsumes the other: + +- `_watch_publish` (deterministic, in-process) adds `os.rename`/`os.replace` and + `Path.rename`/`Path.replace` as SOURCE, plus `builtins.open`/`io.open`/`os.open` + in write modes. It catches every primitive it names, on every run, in + milliseconds — and only those. +- `test_a_concurrent_observer_never_sees_the_record_name_absent` (probabilistic, + out-of-process) republishes the record 200 times in a subprocess while the test + process does nothing but poll `exists()`. It enumerates nothing, so it is the + only half that can catch a primitive nobody listed. It is ONE-SIDED — a hit + proves absence, a miss proves nothing — and therefore cannot go red on correct + code however the two processes are scheduled. + +Measured 2026-08-10 on a 20-core box already at load average 263, ~1.5ms per +publish against ~1us per poll, 150k-300k polls per run: + +| Publish under test | Watcher | Observer | +|---|---|---| +| `os.rename` + `open` (the documented escape) | RED | 10/10, and 10/10 at 60 publishes | +| `unlink` + `write_text` (the previous escape) | RED | 10/10 | +| byte-at-a-time in-place rewrite (the escape before that) | green — caught instead by the hardlink test | 0/6 | +| shipped `write temp + os.replace` | green | 40/40 green, zero absent readings | +| shipped, both processes pinned to ONE core | green | 20/20 green | +| `os.rename` + `open`, pinned to ONE core | RED | 1/15 | + +The two pinned rows are why both halves ship. The observer's sensitivity needs +real parallelism — on a single core the publisher is rarely preempted inside a +window that lasts microseconds — and it is blind by construction to a publish +that never makes the name absent. The watcher is unaffected by scheduling and +covers exactly the named primitives. Sizing follows from that: 200 publishes is +~0.39s, chosen for margin over the 60 that already detected 10/10, and the only +non-assertion guard is a floor of 200 polls, ~0.1% of the measured count, whose +sole job is to notice a poll loop that never ran. A loaded machine costs +detection probability, never a red run. + +The test's stated claim was weakened to match what it proves: it no longer says +*"at the instant **any** file content is written … **nothing** may unlink it"*, +but bounds itself to the primitives `_watch_publish` names, and points at the +observer for the rest. + +**Still declined here:** the observer is a backstop, not a gate — a single-core +CI runner reduces it to ~1/15 per run on the mutation it is aimed at. The +deterministic half is what holds the line there, and the residual is recorded +rather than closed with a longer run, because buying meaningful single-core +sensitivity costs seconds per suite invocation for a probability that still is +not one. diff --git a/scripts/agent-role.py b/scripts/agent-role.py index 2df4249ab..223c2e1ad 100755 --- a/scripts/agent-role.py +++ b/scripts/agent-role.py @@ -104,9 +104,13 @@ def mode_from_marker(marker: dict) -> str: # A record older than this with no heartbeat is stale: it describes a session # that stopped coordinating, and showing it would make the record lie. The value # is unchanged from when this was a lock; only the consequence changed. A stale -# record is filtered out of every display and unlinked by the next `claim`, and -# it can no longer refuse anybody, so breaking one is not an event worth -# announcing any more. +# record is filtered out of every display, and ANOTHER worktree's is unlinked by +# the next `claim`; OURS is replaced by it and never unlinked -- see +# `prune_stale_records`' `keep_canonical`, which exists because our own record is +# stale on any ordinary re-claim and unlinking it before republishing it is the +# one window that leaves this worktree an operator marker with no record. A stale +# record can no longer refuse anybody either, so breaking one is not an event +# worth announcing any more. RECORD_TTL_SECONDS = 2 * 60 * 60 # One directory of per-worktree records. See the module docstring for why this diff --git a/tests/scripts/test_agent_role.py b/tests/scripts/test_agent_role.py index eeff2defd..dcc2c51fc 100644 --- a/tests/scripts/test_agent_role.py +++ b/tests/scripts/test_agent_role.py @@ -11,8 +11,10 @@ from __future__ import annotations import argparse +import builtins import concurrent.futures import importlib.util +import io import json import os import subprocess @@ -50,6 +52,42 @@ def run_role(repo: Path, session: str, *args: str): ) +# The publisher half of the OUTSIDE OBSERVER (see +# `test_a_concurrent_observer_never_sees_the_record_name_absent`). It runs in its +# own process so the observing test process can watch the published name with no +# knowledge of which I/O primitives the publish uses. +# +# 200 publishes: measured at ~1.5ms each on a 20-core box at load average 263 +# (2026-08-10), so the window under observation is ~0.3s, against ~1us per +# `exists()` poll. That budget is chosen for MARGIN, not sensitivity: 60 +# publishes already detected both name-absent mutations 10/10 on that same +# loaded box, and 200 detected 10/10 with 150k-300k polls landing inside the run. +_OBSERVED_PUBLISHES = 200 +_OBSERVED_PUBLISH_LOOP = ''' +import importlib.util, sys +from pathlib import Path + +script, count = Path(sys.argv[1]), int(sys.argv[2]) +spec = importlib.util.spec_from_file_location("agent_role", script) +role = importlib.util.module_from_spec(spec) +sys.modules["agent_role"] = role +spec.loader.exec_module(role) + +# The publish's FILE sequence is the subject. `worktree_id` shells out to +# `git rev-parse` at ~2.7ms a call -- 40x the file work -- so caching it stops +# the observed window being diluted by a subprocess that touches no record. +# `record_path` is the only consumer and its answer is constant for one repo, +# so no path this test looks at changes. +worktree = role.worktree_id() +role.worktree_id = lambda: worktree + +sys.stdout.write("ready\\n") +sys.stdout.flush() +for _ in range(count): + role.write_our_record() +''' + + class _TempRepo: """A throwaway git repo per test. The real checkout is never touched.""" @@ -544,6 +582,18 @@ class RecordPublishAndBadInput(_TempRepo, unittest.TestCase): `unlink(target); target.write_text(new)`: a new inode leaves the hardlink witness intact and no temp is left, but the NAME is transiently absent, which is neither the old record nor the new one. + + A fourth round (issue #296) found the same pattern once more, and stopped + repeating it. Round 3's NAME watcher named four primitives, so a publish + written `os.rename(target, aside)` then `open(target, "w")` escaped all 59 + tests while a concurrent `show` against the slowed window really did return + `rc=3, role=UNDECLARED` -- MEASURED here: the pre-#296 suite is 59/59 GREEN + under that mutation. Any watcher is escapable by one more primitive, so + widening the list cannot be the whole answer. The pin is now two tests that + fail differently: `_watch_publish` names more primitives and catches every + one of them deterministically, and + `test_a_concurrent_observer_never_sees_the_record_name_absent` enumerates + nothing and can therefore catch the next primitive nobody thought of. """ def test_a_publish_replaces_the_record_and_never_rewrites_it_in_place(self) -> None: @@ -591,72 +641,214 @@ def _killed_reclaim(self) -> None: finally: os.chdir(saved) - def test_a_publish_never_leaves_the_record_NAME_absent(self) -> None: - # The two tests above both survive `target.unlink(); target.write_text()` - # (review mutation MINE-B, 2026-08-10): a fresh inode leaves the hardlink - # witness reading the old bytes, and no temp file is left behind. What - # that publish does do is make the NAME transiently absent, which is - # neither "the old record" nor "the new one" -- a `show` landing in the - # window reports an operator marker with no record and exits 3. - # - # So the NAME is watched rather than the bytes. Polling for the window - # would be a race; instead the publish is observed from inside: at the - # instant any file content is written, the published path must already - # resolve, and nothing may unlink it. Both hold for temp + os.replace, - # and neither holds for unlink-then-create. The record has to exist - # first -- "old or new, never absent" says nothing about the first - # publish, which has no old. - run_role(self.repo, "a", "claim", "operator") + def _watch_publish(self, publish) -> tuple[list[str], list[str]]: + """Run `publish` with the record's name watched from INSIDE the process. + + Returns (written-while-absent, name-removals). Both must be empty. + Two families can make the published name stop resolving: removing it + (`unlink`/`remove`) and renaming it AWAY (`rename`/`replace` with the + record as SOURCE -- `os.replace(temp, target)`, the shipped publish, has + it as destination and never removes it). Content writes are watched too, + because a create that finds the name missing proves it was absent an + instant earlier whichever call removed it. + + This half is DETERMINISTIC and only ever as complete as the list below. + Every round of review has fixed one residual here and created the next + escape: the hardlink and residue pins fell to `unlink` + `write_text`, + which fell to `os.rename` + `open`. That is why the list is not the whole + pin -- see `test_a_concurrent_observer_never_sees_the_record_name_absent`, + which enumerates nothing. + """ absent_when_writing: list[str] = [] - unlinked: list[str] = [] - real_write_text = Path.write_text - real_path_unlink = Path.unlink - real_os_unlink = os.unlink - real_os_remove = os.remove + removed: list[str] = [] + real = { + "write_text": Path.write_text, + "path_unlink": Path.unlink, + "path_rename": Path.rename, + "path_replace": Path.replace, + "os_unlink": os.unlink, + "os_remove": os.remove, + "os_rename": os.rename, + "os_replace": os.replace, + "os_open": os.open, + "io_open": io.open, + } saved = os.getcwd() os.chdir(self.repo) try: target = role.record_path() - def watched_write_text(path, *args, **kwargs): + def writing(path) -> None: if not target.exists(): absent_when_writing.append(str(path)) - return real_write_text(path, *args, **kwargs) - def watched_path_unlink(path, *args, **kwargs): + def removing(path) -> None: if Path(path) == target: - unlinked.append(str(path)) - return real_path_unlink(path, *args, **kwargs) + removed.append(str(path)) + + def watched_write_text(path, *args, **kwargs): + writing(path) + return real["write_text"](path, *args, **kwargs) + + def watched_io_open(file, mode="r", *args, **kwargs): + if any(character in mode for character in "wax+"): + writing(file) + return real["io_open"](file, mode, *args, **kwargs) + + def watched_os_open(path, flags, *args, **kwargs): + if flags & (os.O_WRONLY | os.O_RDWR | os.O_CREAT): + writing(path) + return real["os_open"](path, flags, *args, **kwargs) + + def watched_path_unlink(path, *args, **kwargs): + removing(path) + return real["path_unlink"](path, *args, **kwargs) def watched_os_unlink(path, *args, **kwargs): - if Path(path) == target: - unlinked.append(str(path)) - return real_os_unlink(path, *args, **kwargs) + removing(path) + return real["os_unlink"](path, *args, **kwargs) def watched_os_remove(path, *args, **kwargs): - if Path(path) == target: - unlinked.append(str(path)) - return real_os_remove(path, *args, **kwargs) + removing(path) + return real["os_remove"](path, *args, **kwargs) + + def watched_path_rename(path, *args, **kwargs): + removing(path) + return real["path_rename"](path, *args, **kwargs) + + def watched_path_replace(path, *args, **kwargs): + removing(path) + return real["path_replace"](path, *args, **kwargs) + + def watched_os_rename(source, *args, **kwargs): + removing(source) + return real["os_rename"](source, *args, **kwargs) + + def watched_os_replace(source, *args, **kwargs): + removing(source) + return real["os_replace"](source, *args, **kwargs) with mock.patch.object(Path, "write_text", watched_write_text), \ mock.patch.object(Path, "unlink", watched_path_unlink), \ + mock.patch.object(Path, "rename", watched_path_rename), \ + mock.patch.object(Path, "replace", watched_path_replace), \ mock.patch.object(os, "unlink", watched_os_unlink), \ - mock.patch.object(os, "remove", watched_os_remove): - role.write_our_record() + mock.patch.object(os, "remove", watched_os_remove), \ + mock.patch.object(os, "rename", watched_os_rename), \ + mock.patch.object(os, "replace", watched_os_replace), \ + mock.patch.object(os, "open", watched_os_open), \ + mock.patch.object(io, "open", watched_io_open), \ + mock.patch.object(builtins, "open", watched_io_open): + publish() finally: os.chdir(saved) + return absent_when_writing, removed + + def test_a_publish_never_leaves_the_record_NAME_absent(self) -> None: + # The two tests above both survive `target.unlink(); target.write_text()` + # (review mutation MINE-B, 2026-08-10): a fresh inode leaves the hardlink + # witness reading the old bytes, and no temp file is left behind. What + # that publish does do is make the NAME transiently absent, which is + # neither "the old record" nor "the new one" -- a `show` landing in the + # window reports an operator marker with no record and exits 3. + # + # So the NAME is watched rather than the bytes. The claim this test can + # actually support is bounded by `_watch_publish`'s list: of the + # primitives named there, none may remove the published name, and none + # may write content while that name does not resolve. It holds for + # temp + os.replace and fails for unlink-then-create and for + # rename-aside-then-create. The record has to exist first -- "old or new, + # never absent" says nothing about the first publish, which has no old. + run_role(self.repo, "a", "claim", "operator") + + absent_when_writing, removed = self._watch_publish(role.write_our_record) self.assertEqual( - unlinked, [], - "the publish UNLINKED the record name; a reader in that window sees " - "an operator marker with no record, not the old record") + removed, [], + "the publish REMOVED the record name (unlink, or rename away); a " + "reader in that window sees an operator marker with no record, not " + f"the old record: {removed}") self.assertEqual( absent_when_writing, [], "the new bytes were written while the record name did not exist, so " f"the name was transiently absent: {absent_when_writing}") + def test_a_concurrent_observer_never_sees_the_record_name_absent(self) -> None: + # The other half, and the only half that needs no enumeration. A separate + # process republishes this worktree's record `_OBSERVED_PUBLISHES` times + # while THIS process does nothing but ask whether the published name + # resolves. Any publish that removes the name -- by any primitive, named + # or not, including whichever one escapes the watcher next -- is visible + # from out here. + # + # It is deliberately ONE-SIDED: a hit proves the name was absent, a miss + # proves nothing. That asymmetry is the point. The observer cannot go red + # on correct code, because `os.replace` never lets the name stop + # resolving no matter how the two processes are scheduled; scheduling can + # only cost SENSITIVITY, never produce a false failure. So it is safe + # under CI contention in the way a timing assertion never is. + # + # MEASURED 2026-08-10 on a 20-core box already at load average 263, + # publishes at ~1.5ms and polls at ~1us, 150k-300k polls per run: + # * `os.rename` + `open` publish caught 10/10 runs (and 10/10 at 60) + # * `unlink` + `write_text` publish caught 10/10 runs + # * unmutated 40/40 green, zero absent readings + # * unmutated, BOTH PROCESSES PINNED TO ONE CORE 20/20 green + # * `os.rename` + `open`, pinned to one core caught 1/15 + # * byte-at-a-time IN-PLACE rewrite caught 0/6 + # The last two are why this is a backstop and not the whole pin. Its + # sensitivity needs real parallelism -- pinned to a single core the + # publisher is rarely preempted inside a window that lasts microseconds + # -- and it is blind BY CONSTRUCTION to a publish that never makes the + # name absent, which is + # `test_a_publish_replaces_the_record_and_never_rewrites_it_in_place`'s + # subject. The watcher above holds the line deterministically on every + # primitive it names; this holds it probabilistically on the ones nobody + # named. Neither subsumes the other, and only the pair covers both. + run_role(self.repo, "a", "claim", "operator") + saved = os.getcwd() + os.chdir(self.repo) + try: + target = role.record_path() + finally: + os.chdir(saved) + self.assertTrue(target.exists(), "nothing was published to observe") + + publisher = subprocess.Popen( + [sys.executable, "-c", _OBSERVED_PUBLISH_LOOP, + str(ROLE_SCRIPT), str(_OBSERVED_PUBLISHES)], + cwd=self.repo, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True) + try: + # Import and the one `git rev-parse` happen before this line, so the + # observed window is publishes and nothing else. + self.assertEqual(publisher.stdout.readline(), "ready\n") + absent = 0 + polls = 0 + while publisher.poll() is None: + polls += 1 + if not target.exists(): + absent += 1 + errors = publisher.stderr.read() + finally: + publisher.stdout.close() + publisher.stderr.close() + publisher.wait() + + self.assertEqual(publisher.returncode, 0, errors) + # A floor for the observer having LOOKED at all, not a timing assertion: + # the measured count is 150k-300k, so this is ~0.1% of it and can only + # fire if the poll loop did not run. + self.assertGreater(polls, _OBSERVED_PUBLISHES, + "the observer never got to look; sensitivity unknown") + self.assertEqual( + absent, 0, + f"a concurrent observer saw the published record name NOT resolve " + f"{absent} times in {polls} polls across {_OBSERVED_PUBLISHES} " + "publishes: that window is an operator marker with no record") + self.assertTrue(target.exists(), "the publishes left no record behind") + def test_a_reclaim_never_unlinks_its_own_record(self) -> None: # Re-claim must REPLACE, never unlink-then-create. With the publish # killed mid-flight, the record from the previous claim has to survive From 629abd1734c4303d0da5aa4206da0c1f49dda004 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Mon, 10 Aug 2026 21:01:45 +0000 Subject: [PATCH 2/2] fix(tests): the #296 observer could hang the suite, and its sizing was falsified Two MEDIUM findings from the fresh review of 937edcf5 (issue #296). The design it shipped -- a widened in-process watcher AND an out-of-process observer -- stays, and the review itself is the evidence for it: the reviewer found a FIFTH publish shape (write the bytes while the name still resolves, `os.chdir` into the records dir, `os.unlink` the BASENAME, `os.rename` the temp in) that trips NO `_watch_publish` arm and satisfies the hardlink and residue pins, and that the observer alone catches. It is now in the mutation matrix, 10/10 RED multi-core and 10/10 pinned to one core. 1. THE OBSERVER COULD HANG FOREVER INSTEAD OF FAILING. An unread `stderr=subprocess.PIPE` plus an unbounded `while publisher.poll() is None` deadlocks once the child fills the pipe. Reproduced on the SHIPPED, CORRECT publish before the fix: 391 bytes of child stderr per publish never completed -- killed at `timeout 90`, rc=124, no output, spinning a core -- while 155 bytes/publish (~31KB, under this box's 65536-byte pipe) passed in 0.410s. That cliff is reachable by anyone's change, not just a mutation: the child forks `git rev-parse` per publish. A test that cannot finish is worse in a suite everyone must pass than the gap it closes. Child stdout and stderr now go to FILES, which have no capacity to fill, and the diagnostics still reach the failure message. Same 391 bytes/publish now completes in 0.208s; 782KB and 40MB of child stderr pass in under a second. Both loops are additionally bounded by a 60s wall-clock deadline that kills the child and FAILS. Verified in both directions: a child wedged before its ready signal and a child wedged mid-publish each fail at 60.05s. 2. THE SIZING RATIONALE WAS FALSIFIED BY MEASUREMENT, AND THE RECORDED RESIDUAL WAS A HARNESS ARTIFACT. The child comment said caching `worktree_id` "stops the observed window being diluted by a subprocess that touches no record". It did not: `record_path` -> `records_dir` -> `common_dir` still forked `git rev-parse` on every publish. RE-DERIVED here, 20-core box at load 184: 1.467 ms/publish as shipped, 0.163 ms with `common_dir` cached too, 1.041 ms for one bare `git rev-parse` -- so 89% of the window the observer was offered was the very subprocess the comment claimed had been removed. That makes the spec's declination wrong on the cost. Interleaved A/B, 30 paired runs, `taskset -c 3`, load 198-201: `os.rename` + `open` went 0/30 -> 7/30 RED and the basename shape 1/30 -> 9/30 with the one-line cache. Raising the publish count then closes the residual outright, because the loop is now cheap enough to run many more times in the same wall clock -- sweep against the basename shape, 20 runs per cell, multi-core / one core: 200 -> 16/20 and 6/20; 800 -> 19/20 and 14/20; 2000 -> 20/20 and 20/20, with unmutated 0/3 at every count in both regimes. 2000 is the first count that is not probabilistic in EITHER regime and it costs ~0.5s on a ~5s suite, so `_OBSERVED_PUBLISHES` is 2000 and the spec's "Still declined here" paragraph is replaced by what was measured rather than restated. Also addressed, both raised as open concerns rather than findings: * `assertEqual(absent, 0)` would have passed VACUOUSLY if a future publish stopped touching the observed path -- the `exists()` guard, not the observation, was carrying that. The record's bytes are now captured before the run and required to CHANGE after it; the record carries the writer's pid and a fresh heartbeat, so this proves the name observed is the name republished. * `TMPDIR` on NFS/overlay stays untested and is now RECORDED in the spec: both halves assume ordinary POSIX rename and stat semantics, and a filesystem that does not provide them surfaces as an ERROR, not a silent pass. Finding 3 (LOW) is deliberately unchanged: `_watch_publish`'s `Path.rename`, `Path.replace` and `Path.write_text` arms are redundant with the `os.*`/`io.open` ones CPython delegates to, so one `Path.rename` records two removals. The assertions are "this list is empty", so the duplicate is harmless, and the arm keeps the pin honest if CPython ever stops delegating. The spec now says so. `scripts/agent-role.py` is untouched: no product behaviour changes. Mutation matrix at the shipped sizing, 10 runs per cell, load 185 multi-core and 262 pinned to `taskset -c 3` -- the three historical escapes still go RED, and the shipped publish never does: | publish | watcher | observer multi | observer 1-core | hardlink | residue | |---|---|---|---|---|---| | `os.rename` + `open` | 10/10 | 10/10 | 9/10 | - | - | | `unlink` + `write_text` | 10/10 | 10/10 | 10/10 | - | - | | byte-at-a-time in place | - | - | - | 10/10 | - | | bytes, basename unlink, rename in | - | 10/10 | 10/10 | - | - | | shipped temp + `os.replace` | 0/10 | 0/10 | 0/10 | 0/10 | 0/10 | Unmutated flake rate over repeated runs at load average 397-415: observer 0/40 and watcher 0/40, multi-core and pinned to one core alike; slowest observer run 0.92s against the 60s deadline. Poll counts 148k-257k per run, against a floor of 2000. Gates: test_agent_role 60, test_agent_onboard 39, test_agent_start 20 = 119, all green, no count change. `scripts/agent-preflight.sh --quiet` green before the first edit and after the commit (with `--no-require-role`: this session declared no role, so the role gate would report its own state, not the tree's). Rebased onto origin/main 24306364; the #296 roadmap intake row survived. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: Claude-Code:claude-opus-5 [Claude Code] --- .agents/specs/operator-record.md | 124 ++++++++++++++++++------ tests/scripts/test_agent_role.py | 159 +++++++++++++++++++++++-------- 2 files changed, 217 insertions(+), 66 deletions(-) diff --git a/.agents/specs/operator-record.md b/.agents/specs/operator-record.md index b51fdd0f2..dd292ade3 100644 --- a/.agents/specs/operator-record.md +++ b/.agents/specs/operator-record.md @@ -216,42 +216,110 @@ subsumes the other: in write modes. It catches every primitive it names, on every run, in milliseconds — and only those. - `test_a_concurrent_observer_never_sees_the_record_name_absent` (probabilistic, - out-of-process) republishes the record 200 times in a subprocess while the test + out-of-process) republishes the record 2000 times in a subprocess while the test process does nothing but poll `exists()`. It enumerates nothing, so it is the only half that can catch a primitive nobody listed. It is ONE-SIDED — a hit proves absence, a miss proves nothing — and therefore cannot go red on correct code however the two processes are scheduled. -Measured 2026-08-10 on a 20-core box already at load average 263, ~1.5ms per -publish against ~1us per poll, 150k-300k polls per run: - -| Publish under test | Watcher | Observer | -|---|---|---| -| `os.rename` + `open` (the documented escape) | RED | 10/10, and 10/10 at 60 publishes | -| `unlink` + `write_text` (the previous escape) | RED | 10/10 | -| byte-at-a-time in-place rewrite (the escape before that) | green — caught instead by the hardlink test | 0/6 | -| shipped `write temp + os.replace` | green | 40/40 green, zero absent readings | -| shipped, both processes pinned to ONE core | green | 20/20 green | -| `os.rename` + `open`, pinned to ONE core | RED | 1/15 | - -The two pinned rows are why both halves ship. The observer's sensitivity needs -real parallelism — on a single core the publisher is rarely preempted inside a -window that lasts microseconds — and it is blind by construction to a publish -that never makes the name absent. The watcher is unaffected by scheduling and -covers exactly the named primitives. Sizing follows from that: 200 publishes is -~0.39s, chosen for margin over the 60 that already detected 10/10, and the only -non-assertion guard is a floor of 200 polls, ~0.1% of the measured count, whose -sole job is to notice a poll loop that never ran. A loaded machine costs -detection probability, never a red run. +Measured 2026-08-10 on a 20-core box at load average 185 (multi-core) and 262 +(both processes pinned to one core with `taskset -c 3`), 10 runs per cell, at +the sizing this row settled on: + +| Publish under test | Watcher | Observer, multi-core | Observer, one core | +|---|---|---|---| +| `os.rename` + `open` (the documented escape) | RED | 10/10 | 9/10 | +| `unlink` + `write_text` (the previous escape) | RED | 10/10 | 10/10 | +| bytes first, unlink by BASENAME, rename the temp in | green — no arm sees it | 10/10 | 10/10 | +| byte-at-a-time in-place rewrite (the escape before that) | green — caught instead by the hardlink test | 0/10 | 0/10 | +| shipped `write temp + os.replace` | green | 0/10 RED | 0/10 RED | + +The third row is the one that settles the design argument, and the reviewer of +`row/ENG-OPERATOR-RECORD-COVERAGE` found it rather than this row: write the +bytes while the name still resolves, `os.chdir` into the records directory, +`os.unlink` the BASENAME, then `os.rename` the temp in. `_watch_publish`'s +`writing` hook sees the name present, and both of its removal hooks receive a +relative path that does not compare equal to the absolute target, so no arm +fires — and the temp is renamed in, so the residue and hardlink pins stay green +too. The observer is the only test in the suite that fails on it. The fourth row +is the exact converse: the observer is blind by construction to a publish that +never makes the name absent. Neither half subsumes the other, and the two shapes +that only one half catches are now both in the record. The test's stated claim was weakened to match what it proves: it no longer says *"at the instant **any** file content is written … **nothing** may unlink it"*, but bounds itself to the primitives `_watch_publish` names, and points at the observer for the rest. -**Still declined here:** the observer is a backstop, not a gate — a single-core -CI runner reduces it to ~1/15 per run on the mutation it is aimed at. The -deterministic half is what holds the line there, and the residual is recorded -rather than closed with a longer run, because buying meaningful single-core -sensitivity costs seconds per suite invocation for a probability that still is -not one. +### The two residuals #296 left, and what measurement said about them + +**Closed: the single-core sensitivity residual, which cost 0.5s and not +"seconds".** #296 declined to close it on the stated ground that *"buying +meaningful single-core sensitivity costs seconds per suite invocation for a +probability that still is not one"*. That was wrong on the cost, and the reason +is a second measurement-falsified rationale in the same commit — the child +loop's comment said caching `worktree_id` *"stops the observed window being +diluted by a subprocess that touches no record"*, but `record_path` → +`records_dir` → `common_dir` still forked `git rev-parse` on every publish. +Measured on the same box: + +| Child publish loop | ms per publish | +|---|---| +| `worktree_id` cached only (as #296 shipped it) | 1.467 | +| `worktree_id` **and** `common_dir` cached | 0.163 | +| one bare `git rev-parse --git-common-dir` | 1.041 | + +So 89% of the window a half-cached child offered the observer was the very +subprocess the comment claimed had been removed. Caching the second call is one +line, and it moves the observer from probabilistic to deterministic on a single +core. Interleaved A/B, 30 paired runs per arm, `taskset -c 3`, load 198–201: +the `os.rename` + `open` publish went 0/30 → 7/30 RED and the basename shape +1/30 → 9/30 at the old count of 200 publishes. Raising the count then closes it +outright, because the loop is now cheap enough to run many more times in the +same wall clock — sweep against the basename shape, 20 runs per cell: + +| Publishes | Multi-core | One core | Seconds per clean run | +|---|---|---|---| +| 200 | 16/20 | 6/20 | 0.25 / 0.23 | +| 800 | 19/20 | 14/20 | 0.37 / 0.44 | +| 2000 | 20/20 | 20/20 | 0.71 / 0.80 | + +2000 is the first count that is not probabilistic in either regime. It costs +~0.5s on a suite that runs in ~5s, which is why the residual is closed here +rather than recorded a second time. The only non-assertion guard remains a floor +on the poll count; the measured count is 148k–257k polls per run in both +regimes, so the floor sits under 2% of it and can only fire if the poll loop +never ran. + +**Closed: the observer could hang the suite instead of failing it.** As #296 +shipped it, the child's `stderr=subprocess.PIPE` was never read while the parent +spun on `while publisher.poll() is None`, and there was no timeout anywhere in +the test. Measured against the shipped, *correct* publish: 391 bytes of child +stderr per publish never completed at all — killed at 90s, rc=124, spinning a +core throughout — while 155 bytes per publish (~31KB, under this box's 65536-byte +pipe capacity) passed in 0.41s. Nothing exotic is needed to cross that cliff: +the child forks `git rev-parse`, so a few hundred bytes of warning per publish +from anyone's unrelated change is enough, and a test that cannot finish is worse +in a suite everyone must pass than the gap it closes. Child output now goes to +files, which have no capacity to fill — 782KB and 40MB of child stderr both pass +in under a second — and both loops are bounded by a 60s wall-clock deadline that +kills the child and fails the test. Verified both ways: a child wedged before +its ready signal and a child wedged mid-publish each fail at 60.05s instead of +hanging. + +**Recorded, not closed:** `TMPDIR` on an exotic filesystem (NFS, overlay) is +untested. Both halves assume ordinary POSIX rename and stat semantics on the +temp directory. A filesystem that does not provide them would surface as an +ERROR rather than a silent pass, which is the safe direction, so this is +recorded rather than guarded. + +**Kept deliberately:** `_watch_publish` watches `Path.rename`, `Path.replace` +and `Path.write_text` as well as the `os.*` and `io.open` calls they delegate +to, so one `Path.rename` records two removals. That redundancy is harmless — the +assertions are "this list is empty" — and it keeps the pin honest if CPython +ever stops delegating. + +**Unmutated flake rate at the shipped sizing:** 0/40 RED for the observer and +0/40 for the watcher, multi-core and pinned to one core alike, on a box at load +average 397–415. The slowest observer run under that load was 0.92s against the +60s deadline. diff --git a/tests/scripts/test_agent_role.py b/tests/scripts/test_agent_role.py index dcc2c51fc..c2aeb9604 100644 --- a/tests/scripts/test_agent_role.py +++ b/tests/scripts/test_agent_role.py @@ -57,12 +57,30 @@ def run_role(repo: Path, session: str, *args: str): # own process so the observing test process can watch the published name with no # knowledge of which I/O primitives the publish uses. # -# 200 publishes: measured at ~1.5ms each on a 20-core box at load average 263 -# (2026-08-10), so the window under observation is ~0.3s, against ~1us per -# `exists()` poll. That budget is chosen for MARGIN, not sensitivity: 60 -# publishes already detected both name-absent mutations 10/10 on that same -# loaded box, and 200 detected 10/10 with 150k-300k polls landing inside the run. -_OBSERVED_PUBLISHES = 200 +# 2000 publishes at ~0.16ms each (see the child loop below) put the window under +# observation at ~0.33s, against ~1us per `exists()` poll. The count is SIZED +# from measurement, not chosen for margin. MEASURED 2026-08-10 on a 20-core box +# at load average ~200, against the publish that only this half can catch +# (bytes first, unlink by basename, rename the temp in), 20 runs per cell: +# +# publishes | multi-core | one core (taskset -c 3) | clean run, multi / one +# 200 | 16/20 RED | 6/20 RED | 0.25s / 0.23s +# 800 | 19/20 RED | 14/20 RED | 0.37s / 0.44s +# 2000 | 20/20 RED | 20/20 RED | 0.71s / 0.80s +# +# Unmutated stayed 0/3 RED at every count in both regimes. 2000 is the first +# count that is not probabilistic in EITHER regime, and it costs ~0.5s over 200 +# on a suite that runs in ~5s -- which is why the single-core residual #296 +# recorded is closed here rather than recorded again. +_OBSERVED_PUBLISHES = 2000 + +# A wedged child must FAIL this test, not hang the suite. The publish loop takes +# ~0.33s plus interpreter start; 60s is over two orders of magnitude of +# headroom, so reaching it means the child stopped making progress, and the test +# says so instead of spinning until someone kills the run. +_OBSERVER_DEADLINE_SECONDS = 60.0 +_OBSERVED_WINDOW_SECONDS = 0.33 + _OBSERVED_PUBLISH_LOOP = ''' import importlib.util, sys from pathlib import Path @@ -73,13 +91,22 @@ def run_role(repo: Path, session: str, *args: str): sys.modules["agent_role"] = role spec.loader.exec_module(role) -# The publish's FILE sequence is the subject. `worktree_id` shells out to -# `git rev-parse` at ~2.7ms a call -- 40x the file work -- so caching it stops -# the observed window being diluted by a subprocess that touches no record. -# `record_path` is the only consumer and its answer is constant for one repo, -# so no path this test looks at changes. +# The publish's FILE sequence is the subject, so both `git rev-parse` calls on +# the publish path are hoisted out of the loop: `worktree_id` (via +# `record_path`) and `common_dir` (via `records_dir`). Caching only the first +# leaves the second, and MEASURED on a 20-core box at load average 184 +# (2026-08-10) that is where nearly all the time was going: +# * worktree_id cached only 1.467 ms/publish +# * both cached 0.163 ms/publish +# * one bare `git rev-parse` 1.041 ms +# i.e. 89% of the window a half-cached child offers the observer is the +# subprocess it is not supposed to be measuring. Both answers are constant for +# one repo and `record_path`/`records_dir` are their only consumers here, so no +# path this test looks at changes -- it just stops being diluted. worktree = role.worktree_id() role.worktree_id = lambda: worktree +common = role.common_dir() +role.common_dir = lambda: common sys.stdout.write("ready\\n") sys.stdout.flush() @@ -790,23 +817,28 @@ def test_a_concurrent_observer_never_sees_the_record_name_absent(self) -> None: # only cost SENSITIVITY, never produce a false failure. So it is safe # under CI contention in the way a timing assertion never is. # - # MEASURED 2026-08-10 on a 20-core box already at load average 263, - # publishes at ~1.5ms and polls at ~1us, 150k-300k polls per run: - # * `os.rename` + `open` publish caught 10/10 runs (and 10/10 at 60) - # * `unlink` + `write_text` publish caught 10/10 runs - # * unmutated 40/40 green, zero absent readings - # * unmutated, BOTH PROCESSES PINNED TO ONE CORE 20/20 green - # * `os.rename` + `open`, pinned to one core caught 1/15 - # * byte-at-a-time IN-PLACE rewrite caught 0/6 - # The last two are why this is a backstop and not the whole pin. Its - # sensitivity needs real parallelism -- pinned to a single core the - # publisher is rarely preempted inside a window that lasts microseconds - # -- and it is blind BY CONSTRUCTION to a publish that never makes the - # name absent, which is + # RE-MEASURED 2026-08-10 at this file's `_OBSERVED_PUBLISHES` on a + # 20-core box already at load average 185 (multi-core) and 262 (both + # processes pinned to one core with `taskset -c 3`), 10 runs per cell: + # multi-core single core + # * `os.rename` + `open` 10/10 9/10 + # * `unlink` + `write_text` 10/10 10/10 + # * bytes first, unlink by BASENAME, rename the + # temp in -- the one shape NO watcher arm sees 10/10 10/10 + # * byte-at-a-time IN-PLACE rewrite 0/10 0/10 + # * unmutated 0/10 0/10 + # (zero absent readings, both) + # The third row is why this half exists at all: it satisfies the + # hardlink and residue pins and trips no `_watch_publish` arm -- + # `writing` sees the name still present, and both removals arrive as a + # relative basename that does not compare equal to the absolute target + # -- so the observer is the ONLY test that fails on it. The fourth row + # is the converse: this half is blind BY CONSTRUCTION to a publish that + # never makes the name absent, which is # `test_a_publish_replaces_the_record_and_never_rewrites_it_in_place`'s # subject. The watcher above holds the line deterministically on every - # primitive it names; this holds it probabilistically on the ones nobody - # named. Neither subsumes the other, and only the pair covers both. + # primitive it names; this holds it on the ones nobody named. Neither + # subsumes the other, and only the pair covers both. run_role(self.repo, "a", "claim", "operator") saved = os.getcwd() os.chdir(self.repo) @@ -815,31 +847,77 @@ def test_a_concurrent_observer_never_sees_the_record_name_absent(self) -> None: finally: os.chdir(saved) self.assertTrue(target.exists(), "nothing was published to observe") + # Non-vacuity, checked at the end: `absent == 0` also holds for a future + # publish that stops touching this path at all, and the `exists()` guard + # above only proves the path existed BEFORE. The record carries the + # writer's pid and a fresh heartbeat, so requiring the bytes to change + # proves the name the observer watched is the name that was republished. + before = target.read_bytes() + + # Child output goes to FILES, never to a pipe nobody reads. An unread + # `subprocess.PIPE` deadlocks as soon as the child fills the pipe buffer + # (65536 bytes here), and this child forks `git rev-parse` per publish, + # so a few hundred bytes of warning per publish from anyone's unrelated + # change is enough to cross it. MEASURED 2026-08-10 against the shipped, + # correct publish with the pipe in place: 391 bytes of child stderr per + # publish never completed at all -- killed at 90s, rc=124, spinning a + # core -- while 155 bytes/publish (~31KB, under the pipe) passed in + # 0.41s. A file has no capacity to fill, so no volume of child output + # can wedge the observer, and the text still survives for the failure + # message. Everything below is additionally bounded by a wall-clock + # deadline, so a child that stops making progress FAILS this test in + # bounded time instead of hanging a suite everyone has to pass. + logs = tempfile.TemporaryDirectory() + self.addCleanup(logs.cleanup) + out_path = Path(logs.name) / "publisher.out" + err_path = Path(logs.name) / "publisher.err" + deadline = time.monotonic() + _OBSERVER_DEADLINE_SECONDS + + with open(out_path, "wb") as out, open(err_path, "wb") as err: + publisher = subprocess.Popen( + [sys.executable, "-c", _OBSERVED_PUBLISH_LOOP, + str(ROLE_SCRIPT), str(_OBSERVED_PUBLISHES)], + cwd=self.repo, stdout=out, stderr=err) + + def wedged(what: str) -> None: + publisher.kill() + publisher.wait() + self.fail( + f"the publisher {what} within {_OBSERVER_DEADLINE_SECONDS:.0f}s " + f"(~{_OBSERVER_DEADLINE_SECONDS / _OBSERVED_WINDOW_SECONDS:.0f}x " + f"the measured window for {_OBSERVED_PUBLISHES} publishes); " + f"killed. " + f"stderr: {err_path.read_text(encoding='utf-8', errors='replace')[-2000:]!r}") - publisher = subprocess.Popen( - [sys.executable, "-c", _OBSERVED_PUBLISH_LOOP, - str(ROLE_SCRIPT), str(_OBSERVED_PUBLISHES)], - cwd=self.repo, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True) try: - # Import and the one `git rev-parse` happen before this line, so the - # observed window is publishes and nothing else. - self.assertEqual(publisher.stdout.readline(), "ready\n") + # Import and both `git rev-parse` calls happen before "ready", so + # the observed window is publishes and nothing else. + while not out_path.read_bytes().startswith(b"ready\n"): + if publisher.poll() is not None: + break # died before signalling; the returncode check reports it + if time.monotonic() > deadline: + wedged("never signalled ready") absent = 0 polls = 0 while publisher.poll() is None: polls += 1 if not target.exists(): absent += 1 - errors = publisher.stderr.read() + # Every 4096 polls (~4ms of polling), so the deadline costs the + # hot loop nothing measurable and still resolves to milliseconds. + if polls % 4096 == 0 and time.monotonic() > deadline: + wedged("never finished publishing") finally: - publisher.stdout.close() - publisher.stderr.close() + if publisher.poll() is None: + publisher.kill() publisher.wait() + errors = err_path.read_text(encoding="utf-8", errors="replace") self.assertEqual(publisher.returncode, 0, errors) # A floor for the observer having LOOKED at all, not a timing assertion: - # the measured count is 150k-300k, so this is ~0.1% of it and can only - # fire if the poll loop did not run. + # the measured count is 148k-257k polls per run (multi-core and pinned + # to one core alike, load average 312), so this is under 2% of it and + # can only fire if the poll loop did not run. self.assertGreater(polls, _OBSERVED_PUBLISHES, "the observer never got to look; sensitivity unknown") self.assertEqual( @@ -848,6 +926,11 @@ def test_a_concurrent_observer_never_sees_the_record_name_absent(self) -> None: f"{absent} times in {polls} polls across {_OBSERVED_PUBLISHES} " "publishes: that window is an operator marker with no record") self.assertTrue(target.exists(), "the publishes left no record behind") + self.assertNotEqual( + target.read_bytes(), before, + "the record is byte-identical to the one the claim wrote, so the " + "publishes did not touch the name this test observed and " + "`absent == 0` says nothing") def test_a_reclaim_never_unlinks_its_own_record(self) -> None: # Re-claim must REPLACE, never unlink-then-create. With the publish