Files
reliquary/docs/workpad/reports/2026-10-16-17-headless-forks-phase1-recheck.md
T

156 lines
15 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# Phase 1 re-check: headless forks (fix pass `7b9b748`)
- **Reviewer model id**: `claude-opus-5-5[1m]`. Fresh: did not plan, build, review or fix this phase.
- **Date**: 2026-10-16 16:39 +0200 (`date`)
- **Scope**: only the findings named in the brief: I1, I2, I3, M1, M2, M3, M4, M5, M9 from `reports/2026-10-16-16-headless-forks-phase1-review.md`. Diff `20b049e..HEAD` (`7b9b748` code and tests; `4515dbb`, `e60f94c` run log). Run-log sections "Phase 1 fix pass" and "Phase 1 fix pass — Athanor check and deferred Minors", including the builder's re-check flags.
- **Verdict**: all nine resolved. No Critical or Important finding survives. The residual flags are Minor. One new Minor residual comes from the M1 reorder (R1 below).
## Gates I ran
| Gate | Result |
|---|---|
| G-unit `uv run plugins/spire/skills/forks/tests/test_forks.py` | exit 0, `Ran 86 tests in 66.347s`, `OK`, none skipped (16:30:37–16:31:44) |
| G-where `uv run plugins/spire/skills/forks/forks.py where` | exit 0. stdout is one line holding one JSON object: `ok: true`, `spawn: cim-hidden`, binary 2.1.299, `warnings: []` |
| New tests against the unfixed helper | Scratch copy: `forks.py` from `20b049e`, plus the current `tests/test_forks.py`, `preamble.md` and `templates/`. I ran the 26 new or changed tests: **20 failures, 14 errors, 0 unexpected passes** (counted per subtest). Details below. |
| Dead-root tree walk, old vs new | Probe `recheck_tree_probe.py` on the fake table that `ProcessTreeTests` uses. Old `process_tree(rec)` → `[A, A_KID, C, C_KID]` (it claims the reused pid's child A). New, with `alive_until=hb` → `[C, C_KID]`. |
| Leftover processes | `tasklist` python.exe: none |
| Commit hygiene | `20b049e..HEAD` touches only `forks.py`, `test_forks.py` and the run log. No attribution trailers. |
No live `claude` calls were made.
## Findings, one by one
### I1: an error before the model answers was reported as `model_refused`. **Resolved.**
- **The fix.** At `forks.py:1356`, `substituted = bool(models_used) and requested not in models_used`. An empty delta can no longer count as a refusal. The order of the checks is at `:1358-1372`: refused/substituted, then no result, then API error, then `is_error`, then exit code.
- **New classifier.** `api_error_reason` (`:1200-1233`) uses the status code first, then the text. `reason_detail` carries the status plus the first 200 characters of the text.
- **Check against real results.** All 45 result events in the Phase 0 raw streams have `"api_error_status": null`. A successful run is therefore never classified as an API error. The only two `is_error: true` lines in that data are tool results, not result events.
- **Tests that fail on the old helper:**
- `test_api_errors_are_not_model_refused`: 6 of 7 cases fail on the old helper. All of them read `model_refused`. The substitution case still passes, which is correct.
- `test_failures_flags_and_drift` fails on the old helper (`model_refused != is_error`). It now runs the empty-delta path.
- `RuleTests.test_api_error_reason` fails on the old helper with an AttributeError, because the function did not exist yet.
- **Builder flag: the text patterns are a heuristic.** Acceptable as Minor. The patterns only apply when `is_error` is true or a status is present, and the status code wins. The worst misclassification is one error reason swapped for another, never `ok` turned into `failed`.
- **Coverage shift (not a weakening).** The stub's `error` directive used to bill three turns. So "is_error after the requested model billed" (a mid-run error) has no test of its own any more. It reaches the same `is_error` branch through `substituted=False`. Minor.
### I2: walking a dead root's tree could claim and kill unrelated processes. **Resolved.**
- **The fix.** `process_tree(rec, alive_until)` (`:739-771`) takes a dead root's direct children only when `root_ctime < child_ctime <= epoch_to_ctime(alive_until + 1 s)`. With no recorded ctime, or no `alive_until`, a dead root claims nothing. Below a child that has been claimed and verified live, the old rule applies, and it is safe there because that parent pid is live, so it cannot have been reused.
- **Where the bound comes from:**
- `reap_lost` (`:1547`) and `kill_job` (`:1574`) pass `last_alive_at(rt)`, the later of `heartbeat_at` and `ended_at`.
- The supervisor's own calls pass `time.time()` (`:2396`, `:2399`, `:2417`, `:2428`, `:2463`). At those points `claude` exited only just now, or is still alive.
- **The review's scenario.** Reboot or crash, then a reap: every process created after the reboot is newer than the pre-reboot heartbeat, so nothing is claimed.
- **Units.** Windows FILETIME is UTC on both sides, so the conversion is consistent.
- **Tests.** The four `ProcessTreeTests` error on the old helper through the new API. My probe above shows the behaviour itself differs. `test_dead_root_claims_only_children_from_its_lifetime` and `test_dead_root_without_bounds_claims_nothing` would also fail behaviourally on the old walk. `test_reap_lost_bounds_by_heartbeat` would fail too, because the old helper passed no bound. `test_live_root_unchanged` is a regression guard and is meant to pass on both.
- **Builder flag: a child created in the last heartbeat interval is not claimed** (up to `HEARTBEAT_S` = 10 s, less while turns are moving). Acceptable as Minor. The failure mode is now a leaked process, not killing an unrelated one, which is the right trade. One variant of the same gap: when `kill_job` finds the supervisor alive but `claude` already dead, the kill pre-empts the supervisor's own `time.time()` sweep. Children `claude` started in its last ≤ 10 s can then leak. Same class, also Minor.
- **Builder flag: POSIX without `/proc/stat`.** A dead root claims nothing there. Acceptable, since POSIX is out of tested scope (M14 is deferred).
### I3: a `continue` moved the base's `last_hit` forward. **Resolved.**
- **In the supervisor**, `hit_written = e["kind"] != "fork"` (`:2379`). Only a fork bumps the base in the loop (`:2405-2408`).
- **In `_conclude`** (`:1440-1446`), only `train` (its last event) and `fork` (its first event) set `hit_t`. A `continue` sets neither, which matches design §5.
- **Test.** `test_continue_leaves_base_last_hit` fails on the old helper (the base's `last_hit` moved). It also checks that a later fork still refreshes it.
### M1: a kill during finalisation could leave a duplicate ledger line. **Resolved** (the duplicate). One residual window (R1).
- **The fix.**
- `finalize_job` (`:1470-1474`) now writes the result, then the registry, then the ledger.
- `ledger_append` (`:542-555`) skips a job that already has a line.
- A torn last line gets a leading newline.
- **Test.** `test_ledger_append_dedupes_by_job` fails on the old helper.
- **R1 (new, Minor).** The reorder turns the race's outcome from a duplicate line into a missing one.
- *Scenario:* `taskkill` lands between `write_registry` and `ledger_append`. The registry is final. `kill_job`'s `finalize_job` then sees a final entry and returns `None`.
- *Result:* the job never gets a ledger line. Its result file exists, but Phase 2's `usage` would under-count that job's cost.
- The window is still milliseconds. The review offered this order itself.
- *For Phase 2:* `usage` should reconcile the ledger against `results/*.json`, or `kill_job` should append the missing line when `finalize_job` returns `None` and no line exists.
### M2: the stale-lock break had a race and a hot loop. **Resolved.**
- **Hot loop.** A failed `_break` now falls through to the deadline check and the sleep (`:468-480`).
- `test_unbreakable_stale_lock_respects_deadline` fails on the old helper: "acquire spins…, hot loop, no deadline".
- **Staleness.** A lock is stale when its holder's pid + ctime is dead (`_is_stale`, `:421-429`), or when it is older than `LOCK_ABANDONED_S` = 300 s.
- `_try_create` writes the holder's pid and ctime (`:386-388`).
- A lock caught empty or half-written reads as garbage. It is aged by mtime, so a lock being created is never judged stale.
- "Access denied" still counts as alive, which is conservative.
- **Break mechanism.** The waiter renames the lock aside, compares its content, and either deletes it or puts it back with a no-overwrite rename/link (`:431-462`).
- `test_fresh_lock_taken_during_break_survives` fails on the old helper, but for a different reason: the old age rule never judged that fresh, dead-holder lock stale, so the break was never attempted.
- Against the new mechanism the test is still meaningful. A check-then-remove variant would delete the swapped-in fresh lock and fail its token assertion.
- **Builder flag: residual put-back race.** Acceptable as Minor.
- *How it happens:* while a lock is renamed aside, the path is free. A third waiter can create its lock in that window, and the put-back then fails. Two processes then believe they hold the lock.
- *Preconditions, all at once:* a stale lock (holder died mid-section), a second waiter who already re-took it, and a third waiter's 50 ms poll landing inside the milliseconds of the aside window.
- *Damage:* one lost read-modify-write on `registry.json`. The file is written by atomic replace, so it cannot be corrupted.
- *Compared with before:* strictly narrower than the old two-waiter delete. The case is logged (`_diag`) and leaves a named `.broken.lock`.
- `release` is still check-then-remove. With a live holder, though, only the 300 s rule can make its lock stale, so in practice no waiter breaks it.
### M3: a host suspend killed running forks as `orphaned`. **Resolved.**
- **The fix.** `SupClock` (`:2255-2289`):
- A tick gap over `CLOCK_JUMP_S` = 60 s is excluded from `max_minutes`.
- It re-arms the orphan watchdog.
- It flags `clock_jump` and logs it.
- **Legitimate gaps stay below 60 s.** The longest normal loop-body stall is a lock wait of at most `LOCK_WAIT_S` = 45 s plus a few seconds of retries.
- **Tests.**
- `test_clock_jump_not_orphaned_or_timed_out` fails on the old helper (`timeout != ok`). It runs a real `Supervisor` with a 2 h jump injected one second into the run.
- `test_sup_clock_jump` errors on the old helper, because the class did not exist.
- **Builder flags.** All acceptable as Minor:
- **`stalled` still uses the wall clock.** A suspend sets the flag, but nothing in Phase 1 kills on it. The Phase 3 text must not treat `stalled` combined with `clock_jump` as a hung fork.
- **`wall_s` includes the suspend.** This only affects reporting.
- **A backwards clock jump is not detected.** It delays the orphan or timeout check by the size of the jump. It happens only on a manual clock change, since `time.time()` is UTC and DST does not move it.
- **`kill`/`expire` do not refresh the orchestrator stamp.** This belongs in the Phase 3 text, as the review said.
### M4: N3 left two gaps. **Resolved.**
- **The fix.**
- `CHILD_REFUSED` (`:127`) now includes `kill`, `expire` and `init`. The refusal is in the dispatch at `:2627`.
- `stamp_orchestrator`/`touch_orchestrator` (`:1494-1512`) do nothing under `SPIRE_FORKS_CHILD`. By grep, all stamp sites go through them: `train` `:2107`, `fork` `:2156`, `continue` `:2225`, `wait` `:2526`, and `touch_orchestrator` (`:1511`, called at `:2493` and `:2547`).
- **Tests.** `test_child_refuses_kill_expire_init` and `test_child_does_not_stamp_orchestrator` both fail on the old helper. The marker cannot leak into other tests, because `Base.setUp` patches `os.environ` per test and pops the marker.
- **Outside M4, on record only.** `_supervise` (internal) and `tick` (Phase 2) are not refused inside a fork either.
### M5: the `--permission-mode` value set was stale against 2.1.299. **Resolved.**
- **The fix.** At `:69`, the set matches the 2.1.299 `--help` list. `plan` is still refused, and `default` is now "unknown". The `allowed` list leaves out `plan` (`:1826-1827`).
- **Test.** `test_permission_modes_match_2_1_299` fails on the old helper: it accepted `default`.
### M9: `ANTHROPIC_BASE_URL` sat on neither scrub list. **Resolved.**
- **The fix.** The variable is on `SCRUB_KEEP` (`:114`). `where` always returns a `warnings` list, and warns when the value, trailing slash and case ignored, is not `https://api.anthropic.com` (`:1778-1793`). The exit code stays 0.
- **Tests.** `test_where_warns_on_base_url` errors on the old helper (KeyError `warnings`). `ScrubTests.test_unknown` fails on the old helper.
- **Not done.** The review's optional "record the value per base" was not built. It was optional.
- **Builder flag: an empty value warns.** Acceptable as Minor. The output is a cosmetic false warning (`ok: true`, exit 0), and the empty value passes through to the child unchanged.
## Weakened checks and tests that cannot fail
I diffed `20b049e..HEAD` on `test_forks.py`. Every removed line is accounted for:
- **`scrub_unknown`** expected `["ANTHROPIC_BASE_URL", "CLAUDE_CODE_NEW_THING"]` and now expects `["CLAUDE_CODE_NEW_THING"]`. This is M9's intended change. The fix pass also added `scrub_class("ANTHROPIC_BASE_URL") == "keep"`.
- **`test_stale_lock_broken` became `test_dead_holder_lock_broken_at_once`.** The new test is stricter: it adds a time bound under 1.5 s and checks that no `.lock` file is left. Breaking by age is still covered, by `test_abandoned_lock_broken_by_age` and `test_garbage_stale_lock_broken_by_mtime`.
- **`LOCK_STALE_S` became `LOCK_ABANDONED_S`** in the garbage-lock test and the injected-clock test. This is M2's intended change. The assertions are unchanged.
- **`test_fresh_lock_not_broken` is stronger.** It now uses a live holder aged 60 s (older than the old 30 s threshold) and adds a fresh garbage lock.
- **The stub's `error` directive** now bills nothing. The expectations in `test_failures_flags_and_drift` are unchanged, and the test now runs the more realistic path. See the coverage note under I1.
Other checks:
- **Skip guard.** The only `skipTest` added (`ProcessTreeTests`, when there is no epoch→ctime conversion) cannot trigger on Windows. The suite reported no skips.
- **Tests that cannot fail.** None found. Every new test either fails on the unfixed helper or is a stated regression guard (`test_live_root_unchanged`, `test_abandoned_lock_broken_by_age`).
## Surviving Critical / Important
None.
## Residual Minors for the record (not re-check failures)
- **I1:** the text heuristic; no test for "error after billing the requested model".
- **I2:** a child started in the last heartbeat interval is not claimed (also through `kill_job` when the supervisor is alive and `claude` is dead); POSIX without `/proc/stat` claims nothing.
- **M1 / R1:** a kill between the registry write and the ledger append leaves the job with no ledger line. Phase 2 `usage` should reconcile against `results/`.
- **M2:** the three-waiter put-back race; `release` is still check-then-remove.
- **M3:** `stalled` and `wall_s` count the suspend; backwards jumps are not detected; `kill`/`expire` do not stamp (Phase 3 text).
- **M9:** an empty value warns.
## Unplanned additions in the fix pass (on record)
- New failure reasons: `usage_limit`, `overloaded`, `prompt_too_long`, `api_error`. The review asked only that API errors stop reading `model_refused` and suggested carrying the status in the detail. The Phase 3 text needs to list these reasons.
- New `clock_jump` flag and the `sup.log` jump line.
- `where` always carries `warnings`, even when the list is empty.
- `ledger_append` repairs a torn last line, and now returns a bool.
- The stub directives `apierr=` and `errtext=`.
- The `.broken.lock` leftover naming (matched by `.gitignore`'s `*.lock`).