The production-hook-fire-log isolation guard is per-test, but its claim is per-suite #809

Closed
opened 2026-08-21 20:07:56 +02:00 by timothy · 5 comments
Owner

Spawned by #785, which shipped the defect this guard exists to catch and was not caught by it.

The gap

scripts/tests/conftest.py's autouse isolate_hook_fire_log fixture monkeypatches ETV_HOOK_FIRE_LOG_DIR into os.environ at test setup, so hooks driven as subprocesses log to a tmp dir instead of $HOME/.cache/ersatztv/hook-fire/. That is the #776 invariant: tests never write to the real log at all.

test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log is the guard, and its docstring states the scope as:

conftest.py must isolate every test, not just this file's.

What it actually checks is narrower:

  1. ETV_HOOK_FIRE_LOG_DIR is set for the test currently running;
  2. a hook it drives, in its own sandbox env, does not change any mtime under the real log dir.

Neither reaches another test file. A suite that does _ENV = {**os.environ, ...} at MODULE level captures the environment as it was at import/collection time — before the autouse fixture ran — and hands that stale mapping to every subprocess it launches.

Measured

scripts/tests/test_worktree_ownership_guard.py (added in #785) did exactly that. Before it was caught, the production log held 1,488 records for its two synthetic session ids (session-aaaa-1111, session-bbbb-2222); one further run added 28 more. Every test in the file passed throughout, and test_the_suite_does_not_write_to_the_PRODUCTION_log stayed green, because the fire-log library is fail-open by design — a hook whose logging misfires must behave exactly as an uninstrumented one, so nothing can surface from the hook side.

Why it matters beyond tidiness: scripts/hook-fire-log.sh report is the surface docs/guard-inventory.md cites as the observability claim for every guard still graded NONE. A log carrying test artifacts answers a different question while looking identical — the inference problem #776 exists to abolish, one layer up. The stray records also outlive the session: they accumulate on dev machines and on the persistent CI runner's $HOME.

What #785 shipped instead

A per-file pin: test_worktree_ownership_guard.py::test_the_subprocess_env_CARRIES_the_isolated_hook_fire_log_dir asserts the env handed to subprocesses carries the fixture's dir. Witnessed red by reintroducing the import-time snapshot. That protects one file, which is the same shape as the guard it complements — the next suite to snapshot os.environ is unprotected again.

Scope

The honest difficulty, stated so it is not rediscovered: the obvious general check — diff the production log dir before and after each test — is racy, because a real interactive session's hooks fire into that same directory while the suite runs. A guard that goes red because the developer used the Bash tool during a test run teaches its readers to ignore it, which is #806's failure shape.

So the likely answers are structural rather than observational, e.g.:

  • a conftest-level check that no test module holds a module-level dict derived from os.environ (a source-text predicate — note fixing-a-parser-bug-introduces-the-next-one; budget rounds or reject it);
  • pointing the fixture at a dir and asserting at session teardown that the real dir gained no file whose session id matches a test-shaped pattern;
  • removing the failure mode instead of detecting it — e.g. a shared run_hook() helper in conftest.py that every hook-driving suite uses, so there is one place that builds the env and no per-file opportunity to snapshot it. This is the fix-the-boundary-not-the-site option and is probably the right one.

Also worth correcting either way: the existing guard's docstring should state the scope it checks rather than the scope it wants.

Done-when

  • The isolation invariant is enforced for suites other than test_hook_fire_log.py, or the guard's docstring is narrowed to what it checks and the gap recorded
  • Whatever ships is witnessed red against the #785 defect (a module-level {**os.environ} snapshot in another suite)
  • No new guard that is red on a normal developer checkout (docs/decisions/records/testing/guard-derives-population-from-source.md)
  • Adversarial review passed
Spawned by #785, which shipped the defect this guard exists to catch and was not caught by it. ## The gap `scripts/tests/conftest.py`'s autouse `isolate_hook_fire_log` fixture monkeypatches `ETV_HOOK_FIRE_LOG_DIR` into `os.environ` at test setup, so hooks driven as subprocesses log to a tmp dir instead of `$HOME/.cache/ersatztv/hook-fire/`. That is the #776 invariant: tests never write to the real log at all. `test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log` is the guard, and its docstring states the scope as: > `conftest.py` must isolate every test, not just this file's. What it actually checks is narrower: 1. `ETV_HOOK_FIRE_LOG_DIR` is set **for the test currently running**; 2. a hook **it** drives, in **its own** sandbox env, does not change any mtime under the real log dir. Neither reaches another test file. A suite that does `_ENV = {**os.environ, ...}` at MODULE level captures the environment as it was at import/collection time — before the autouse fixture ran — and hands that stale mapping to every subprocess it launches. ## Measured `scripts/tests/test_worktree_ownership_guard.py` (added in #785) did exactly that. Before it was caught, the production log held **1,488** records for its two synthetic session ids (`session-aaaa-1111`, `session-bbbb-2222`); one further run added 28 more. Every test in the file passed throughout, and `test_the_suite_does_not_write_to_the_PRODUCTION_log` stayed green, because the fire-log library is **fail-open by design** — a hook whose logging misfires must behave exactly as an uninstrumented one, so nothing can surface from the hook side. Why it matters beyond tidiness: `scripts/hook-fire-log.sh report` is the surface `docs/guard-inventory.md` cites as the observability claim for every guard still graded `NONE`. A log carrying test artifacts answers a different question while looking identical — the inference problem #776 exists to abolish, one layer up. The stray records also outlive the session: they accumulate on dev machines and on the persistent CI runner's `$HOME`. ## What #785 shipped instead A per-file pin: `test_worktree_ownership_guard.py::test_the_subprocess_env_CARRIES_the_isolated_hook_fire_log_dir` asserts the env handed to subprocesses carries the fixture's dir. Witnessed red by reintroducing the import-time snapshot. That protects **one file**, which is the same shape as the guard it complements — the next suite to snapshot `os.environ` is unprotected again. ## Scope The honest difficulty, stated so it is not rediscovered: the obvious general check — diff the production log dir before and after each test — is **racy**, because a real interactive session's hooks fire into that same directory while the suite runs. A guard that goes red because the developer used the Bash tool during a test run teaches its readers to ignore it, which is #806's failure shape. So the likely answers are structural rather than observational, e.g.: - a conftest-level check that no test module holds a module-level dict derived from `os.environ` (a source-text predicate — note `fixing-a-parser-bug-introduces-the-next-one`; budget rounds or reject it); - pointing the fixture at a dir and asserting **at session teardown** that the real dir gained no file whose session id matches a test-shaped pattern; - removing the failure mode instead of detecting it — e.g. a shared `run_hook()` helper in `conftest.py` that every hook-driving suite uses, so there is one place that builds the env and no per-file opportunity to snapshot it. This is the `fix-the-boundary-not-the-site` option and is probably the right one. Also worth correcting either way: the existing guard's docstring should state the scope it checks rather than the scope it wants. ## Done-when - [x] The isolation invariant is enforced for suites other than `test_hook_fire_log.py`, or the guard's docstring is narrowed to what it checks and the gap recorded - [x] Whatever ships is witnessed red against the #785 defect (a module-level `{**os.environ}` snapshot in another suite) - [x] No new guard that is red on a normal developer checkout (`docs/decisions/records/testing/guard-derives-population-from-source.md`) - [x] Adversarial review passed
timothy added the ci-cdpriority: medium labels 2026-08-21 20:08:12 +02:00
Author
Owner

Observed on 2026-08-22 while running the full scripts/tests suite locally during #772/#792:

FAILED scripts/tests/test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log
1 failed, 909 passed, 2 skipped

The same suite passed on an immediate clean re-run (910 passed) and the file passes in isolation (78 passed). The difference between the two runs was another agent session doing tool calls on this machine at the same time.

That fits this issue's subject and sharpens it: the assertion compares mtimes of the REAL ~/.cache/ersatztv/hook-fire/*.jsonl before and after driving its own hook, so it does not actually measure "did THIS SUITE write to the production log" — it measures "did anything on this host write to it during that window". Two Claude sessions on one machine is the normal working mode in this repo (CLAUDE.md -> "Working in parallel with other sessions"), and every one of them fires merge-consent/BOM/worktree hooks on ordinary tool calls.

So the guard has a false-positive mode that scales with exactly the workflow the repo encourages, and its red says "the suite polluted the production log" when the true statement is "someone did". Worth folding into the fix here: the per-suite claim needs a source of truth that can attribute a write, not a whole-directory mtime — e.g. compare the SET of records, or key on a marker the suite's own fires carry.

No action taken on this branch; recording it because a mid-session red here reads as a real isolation failure and cost a re-run to dismiss.

Observed on 2026-08-22 while running the full `scripts/tests` suite locally during #772/#792: ``` FAILED scripts/tests/test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log 1 failed, 909 passed, 2 skipped ``` The same suite passed on an immediate clean re-run (910 passed) and the file passes in isolation (78 passed). The difference between the two runs was **another agent session doing tool calls on this machine at the same time**. That fits this issue's subject and sharpens it: the assertion compares mtimes of the REAL `~/.cache/ersatztv/hook-fire/*.jsonl` before and after driving its own hook, so it does not actually measure "did THIS SUITE write to the production log" — it measures "did anything on this host write to it during that window". Two Claude sessions on one machine is the normal working mode in this repo (`CLAUDE.md` -> "Working in parallel with other sessions"), and every one of them fires merge-consent/BOM/worktree hooks on ordinary tool calls. So the guard has a false-positive mode that scales with exactly the workflow the repo encourages, and its red says "the suite polluted the production log" when the true statement is "someone did". Worth folding into the fix here: the per-suite claim needs a source of truth that can attribute a write, not a whole-directory mtime — e.g. compare the SET of records, or key on a marker the suite's own fires carry. No action taken on this branch; recording it because a mid-session red here reads as a real isolation failure and cost a re-run to dismiss.
Author
Owner

Observation from #788 (2026-08-26), offered as evidence rather than a fix — this is a second, distinct manifestation of the permeability this issue is about.

test_the_suite_does_not_write_to_the_PRODUCTION_log failed once during a full-suite run and did not reproduce on a re-run of the identical tree. An independent reviewer working the same branch saw the same failure and the same non-reproduction, so it is not local to one machine or one checkout.

The mechanism is different from the stale-module-level-_ENV one in the body. The guard snapshots mtimes under the real ~/.cache/ersatztv/hook-fire/ at test start and compares after driving its own hook — so any concurrent writer to that shared directory during the window fails it, no stale env required. Concurrent Claude Code sessions and subagents fire hooks continuously and write there; three sessions were active on this repo at the time.

So the per-test/per-suite scope gap this issue names has a sibling: the guard reads a shared mutable directory it does not own, which makes it non-deterministic under concurrency independent of how well conftest.py isolates the suite. Worth folding into the fix, since widening the claim from per-test to per-suite would not close this one — a per-suite snapshot over a shared dir has the same exposure, just a longer window.

No action taken here; #788 measured it and moved on.

Observation from #788 (2026-08-26), offered as evidence rather than a fix — this is a **second, distinct manifestation** of the permeability this issue is about. `test_the_suite_does_not_write_to_the_PRODUCTION_log` failed once during a full-suite run and did **not** reproduce on a re-run of the identical tree. An independent reviewer working the same branch saw the same failure and the same non-reproduction, so it is not local to one machine or one checkout. The mechanism is different from the stale-module-level-`_ENV` one in the body. The guard snapshots mtimes under the real `~/.cache/ersatztv/hook-fire/` at test start and compares after driving its own hook — so **any concurrent writer to that shared directory during the window fails it**, no stale env required. Concurrent Claude Code sessions and subagents fire hooks continuously and write there; three sessions were active on this repo at the time. So the per-test/per-suite scope gap this issue names has a sibling: the guard reads a **shared mutable directory it does not own**, which makes it non-deterministic under concurrency independent of how well `conftest.py` isolates the suite. Worth folding into the fix, since widening the claim from per-test to per-suite would not close this one — a per-suite snapshot over a shared dir has the same exposure, just a longer window. No action taken here; #788 measured it and moved on.
Author
Owner

Evidence from an unrelated session (the #786/#789 work), recorded because it is a concrete
reproduction rather than a theory.

test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log went red on a full
pytest scripts/tests run, on a diff that touches no hook and no fire-log file:

E   At index 31 diff: 1787939233390888936 != 1787939234738882672
scripts/tests/test_hook_fire_log.py:1137: AssertionError
FAILED ... test_the_suite_does_not_write_to_the_PRODUCTION_log
1 failed, 1160 passed, 2 skipped in 324.82s

Cause, measured not inferred. The test snapshots st_mtime_ns of every
~/.cache/ersatztv/hook-fire/*.jsonl before its own hook run and compares after. That directory is
in $HOMEshared across every worktree and every concurrent Claude session. A cold-review
subagent was running in its own worktree at the time. During the window:

$ find ~/.cache/ersatztv/hook-fire -name '*.jsonl' -mmin -15
.../6ec0e53e-....jsonl   <- this session
.../0f976a80-....jsonl   <- another session
.../b2c0098c-....jsonl   <- another session

Three session logs written inside the comparison window; the mtime multiset moved; the test fired.

It is green in isolation, both before and after the change (pytest scripts/tests/test_hook_fire_log.py78 passed, 2 skipped), and the same full suite was green on
runs where no second session was active (1161 / 1175 passed).

This is exactly the gap this issue names — the isolation is per-test (ETV_HOOK_FIRE_LOG_DIR is set
for the test's own hook) while the CLAIM is per-suite ("the suite does not write to the production
log"). What the assertion actually measures is "nothing on this machine wrote to the shared
directory", which is not a property of the suite at all. CI does not hit it because one job runs
alone; a developer with a second session open does, and the red names a file they did not touch.

Worth noting for whoever fixes it: ETV_HOOK_FIRE_LOG_DIR being set correctly is genuinely asserted
at the top of the same test, and that part is sound. It is only the before/after mtime comparison
over a $HOME path that is machine-scoped rather than suite-scoped. Refs #822.

Evidence from an unrelated session (the #786/#789 work), recorded because it is a concrete reproduction rather than a theory. `test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log` went red on a full `pytest scripts/tests` run, on a diff that touches no hook and no fire-log file: ``` E At index 31 diff: 1787939233390888936 != 1787939234738882672 scripts/tests/test_hook_fire_log.py:1137: AssertionError FAILED ... test_the_suite_does_not_write_to_the_PRODUCTION_log 1 failed, 1160 passed, 2 skipped in 324.82s ``` **Cause, measured not inferred.** The test snapshots `st_mtime_ns` of every `~/.cache/ersatztv/hook-fire/*.jsonl` before its own hook run and compares after. That directory is in `$HOME` — **shared across every worktree and every concurrent Claude session**. A cold-review subagent was running in its own worktree at the time. During the window: ``` $ find ~/.cache/ersatztv/hook-fire -name '*.jsonl' -mmin -15 .../6ec0e53e-....jsonl <- this session .../0f976a80-....jsonl <- another session .../b2c0098c-....jsonl <- another session ``` Three session logs written inside the comparison window; the mtime multiset moved; the test fired. **It is green in isolation**, both before and after the change (`pytest scripts/tests/test_hook_fire_log.py` → `78 passed, 2 skipped`), and the same full suite was green on runs where no second session was active (1161 / 1175 passed). This is exactly the gap this issue names — the isolation is per-test (`ETV_HOOK_FIRE_LOG_DIR` is set for the test's own hook) while the CLAIM is per-suite ("the suite does not write to the production log"). What the assertion actually measures is "nothing on this machine wrote to the shared directory", which is not a property of the suite at all. CI does not hit it because one job runs alone; a developer with a second session open does, and the red names a file they did not touch. Worth noting for whoever fixes it: `ETV_HOOK_FIRE_LOG_DIR` being set correctly is genuinely asserted at the top of the same test, and that part is sound. It is only the before/after mtime comparison over a `$HOME` path that is machine-scoped rather than suite-scoped. Refs #822.
timothy added the in-progress label 2026-08-28 23:10:33 +02:00
Author
Owner

Claiming #809 + #822 together as a single-mechanism bundle: both are the same guard
(scripts/tests/test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log) and the
same conftest isolation seam. #822 is the oracle reading global mutable state; #809 is the isolation
being per-file rather than per-suite. Both bodies independently land on the same structural answer —
make the production path unreachable from the suite by construction, with one place that builds the
hook subprocess env — so fixing them separately would mean building the mechanism twice.

Claude Code session, worktree off origin/main.

Claiming #809 + #822 together as a single-mechanism bundle: both are the same guard (`scripts/tests/test_hook_fire_log.py::test_the_suite_does_not_write_to_the_PRODUCTION_log`) and the same conftest isolation seam. #822 is the oracle reading global mutable state; #809 is the isolation being per-file rather than per-suite. Both bodies independently land on the same structural answer — make the production path unreachable from the suite by construction, with one place that builds the hook subprocess env — so fixing them separately would mean building the mechanism twice. Claude Code session, worktree off `origin/main`.
Author
Owner

Closing record

Outcome: Fixed in http://192.168.1.95:3000/timothy/ersatztv/pulls/874, together with #822 — the two are one mechanism. The isolation is now structural and cross-suite: scripts/tests/conftest.py's pytest_configure sets ETV_HOOK_FIRE_LOG_DIR before collection, and a subprocess.Popen wrapper (scripts/tests/hook_fire_isolation.py) fails any launch that does not CARRY an isolated dir. The guard's docstring was not narrowed — the gap was closed.

Root cause: The isolation was an autouse function fixture, which runs at test setup. By then every test module has been imported, so it could not reach a module holding a {**os.environ} snapshot — and, not anticipated by this issue, it could not reach a module- or session-scoped fixture either, since those are set up outside any single test. Measured on the pre-change tree: of 83 launches resolving to $HOME/.cache/ersatztv/hook-fire, 37 were during collection and 44 inside such fixtures; only 2 resembled the module-level-snapshot route this issue names.

Decisions/conventions changed: Added testing.suite-isolated-from-production-hook-fire-log (docs/decisions/records/testing/); catalog regenerated.

Reusable knowledge:

  1. The population that mattered was launches, not source. This issue proposed a source-text scan for module-level os.environ dicts (and flagged that such a predicate costs rounds). A source scan would have found nothing and reported the suite clean; only instrumenting Popen and running the suite produced the real population.
  2. Instrument Popen alone. subprocess.run, call and check_output all reach it, so a census wrapping run as well counts every launch twice — the first census here did, and doubled every published figure until cold review refuted it.
  3. pytest_configure runs before collection, so a value set there is captured by a module-level {**os.environ} — which turns the #785 defect class from something to detect into something that cannot happen.
  4. Model both branches of a ${VAR:-${OTHER:-x}} default. A check comparing against one resolved production path is blind to the other; 81 of the 83 from-scratch launches here landed in the branch such a check cannot see.
  5. assert isolation_violation(os.environ) is None prints the whole environment, API keys included, into the failure output — pytest rewrites the expression and reprs every sub-expression. Bind the result first.
  6. Popen accepts cwd as str/bytes/PathLike but not an int fd, and accepts a bytes-keyed or bytes-valued env. A guard that raises TypeError on a legal launch is broken, not strict.

Verification: PYTHONPATH=. python3 -m pytest scripts/tests -q1228 passed / 2 skipped (base 1224/2). Green with HOME unset, HOME=/tmp and HOME="". Nine clause mutations witnessed red, each disarmed alone and restored. Zero unintended guard rejections. Six cold adversarial rounds, three cross-family; the sixth found no code or documentation defects.

Deferred: The launch guard does not see a child started outside Popen (os.execve, os.posix_spawn), one that re-execs, or a script that unsets the variable itself; containment is a string comparison, so a case-variant spelling on a case-insensitive filesystem is cleared; and "carries an isolated dir" is wider than "carries a good dir". None occur in the suite today and all are enumerated in ProductionLogGuard's docstring rather than left to be rediscovered.

Docs updated: docs/guard-inventory.md (narrative rewritten to the closed state, both withdrawn shapes recorded so neither is re-adopted), the new decision record + regenerated docs/decisions/README.md, docs/README.md, scripts/hook-fire-log.sh, and stale docstrings in test_worktree_ownership_guard.py and test_guard_populations_derive_from_git.py.

## Closing record **Outcome:** Fixed in http://192.168.1.95:3000/timothy/ersatztv/pulls/874, together with #822 — the two are one mechanism. The isolation is now structural and cross-suite: `scripts/tests/conftest.py`'s `pytest_configure` sets `ETV_HOOK_FIRE_LOG_DIR` **before collection**, and a `subprocess.Popen` wrapper (`scripts/tests/hook_fire_isolation.py`) fails any launch that does not CARRY an isolated dir. The guard's docstring was not narrowed — the gap was closed. **Root cause:** The isolation was an autouse *function* fixture, which runs at test setup. By then every test module has been imported, so it could not reach a module holding a `{**os.environ}` snapshot — and, not anticipated by this issue, it could not reach a module- or session-scoped fixture either, since those are set up outside any single test. Measured on the pre-change tree: of 83 launches resolving to `$HOME/.cache/ersatztv/hook-fire`, **37** were during collection and **44** inside such fixtures; only **2** resembled the module-level-snapshot route this issue names. **Decisions/conventions changed:** Added `testing.suite-isolated-from-production-hook-fire-log` (`docs/decisions/records/testing/`); catalog regenerated. **Reusable knowledge:** 1. *The population that mattered was launches, not source.* This issue proposed a source-text scan for module-level `os.environ` dicts (and flagged that such a predicate costs rounds). A source scan would have found nothing and reported the suite clean; only instrumenting `Popen` and running the suite produced the real population. 2. *Instrument `Popen` alone.* `subprocess.run`, `call` and `check_output` all reach it, so a census wrapping `run` as well counts every launch twice — the first census here did, and doubled every published figure until cold review refuted it. 3. *`pytest_configure` runs before collection*, so a value set there **is** captured by a module-level `{**os.environ}` — which turns the #785 defect class from something to detect into something that cannot happen. 4. *Model both branches of a `${VAR:-${OTHER:-x}}` default.* A check comparing against one resolved production path is blind to the other; 81 of the 83 from-scratch launches here landed in the branch such a check cannot see. 5. *`assert isolation_violation(os.environ) is None` prints the whole environment*, API keys included, into the failure output — pytest rewrites the expression and reprs every sub-expression. Bind the result first. 6. `Popen` accepts `cwd` as str/bytes/`PathLike` but **not** an int fd, and accepts a bytes-keyed or bytes-valued `env`. A guard that raises `TypeError` on a legal launch is broken, not strict. **Verification:** `PYTHONPATH=. python3 -m pytest scripts/tests -q` → **1228 passed / 2 skipped** (base 1224/2). Green with `HOME` unset, `HOME=/tmp` and `HOME=""`. Nine clause mutations witnessed red, each disarmed alone and restored. Zero unintended guard rejections. Six cold adversarial rounds, three cross-family; the sixth found no code or documentation defects. **Deferred:** The launch guard does not see a child started outside `Popen` (`os.execve`, `os.posix_spawn`), one that re-execs, or a script that unsets the variable itself; containment is a string comparison, so a case-variant spelling on a case-insensitive filesystem is cleared; and "carries an isolated dir" is wider than "carries a *good* dir". None occur in the suite today and all are enumerated in `ProductionLogGuard`'s docstring rather than left to be rediscovered. **Docs updated:** `docs/guard-inventory.md` (narrative rewritten to the closed state, both withdrawn shapes recorded so neither is re-adopted), the new decision record + regenerated `docs/decisions/README.md`, `docs/README.md`, `scripts/hook-fire-log.sh`, and stale docstrings in `test_worktree_ownership_guard.py` and `test_guard_populations_derive_from_git.py`.
timothy removed the in-progress label 2026-08-29 04:32:51 +02:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: timothy/ersatztv#809