Skip to content

fix(tests): stop the LSP suite writing into the operator's real agent.log - #61

Closed
pai-scaffolde wants to merge 3 commits into
mainfrom
fix/lsp-test-log-pollution
Closed

fix(tests): stop the LSP suite writing into the operator's real agent.log#61
pai-scaffolde wants to merge 3 commits into
mainfrom
fix/lsp-test-log-pollution

Conversation

@pai-scaffolde

Copy link
Copy Markdown
Collaborator

The problem

The LSP test suite wrote language-server lifecycle records into ~/.hermes/logs/agent.log. That log is the only durable record of LSP client lifecycle — gateway uptime is short (median 4.19h over 129 restarts), so a live ps snapshot usually cannot answer "is LSP accumulation bounded". The log is the instrument.

Replaying log_active / log_reaped pairs over the polluted log reported 20 concurrent clients climbing with no balancing reaps. Filtering the synthetic $TMPDIR roots collapsed that to 7, spawns and reaps balanced exactly. Ground truth at the time was 0 live processes.

So the pollution did not merely inflate a number — it inverted the verdict: unfiltered it read as UNBOUNDED (which would have justified building an LRU cap), filtered it read as BOUNDED. A live false-signal path into a build decision.

Two independent causes, both closed

1. tests/conftest.py sandboxed HERMES_HOME only when it was unset.

if not os.environ.get("HERMES_HOME"):   # ← the hole

That left it open for exactly the people most likely to hit it: anyone running the suite from inside a Hermes agent or gateway process, where HERMES_HOME is exported and points at the real root. There the sandbox was skipped, import-time setup_logging() attached rotating handlers to the real agent.log, and every propagating logger in the suite wrote into it.

The sandbox is now unconditional. With HERMES_HOME unset — CI and default local runs — behavior is unchanged: both the old and new paths create the same tempdir sandbox. The only behavior that changes is the case that was already broken.

tests/test_log_isolation.py already guarded this property and was genuinely failing under a preset HERMES_HOME:

E  AssertionError: HERMES_HOME pointed at the operator's real home (/Users/gary/.hermes)
E  when conftest loaded; import-time setup_logging() writes to their agent.log

It now passes.

2. The caplog_lsp fixture left propagation on.

caplog.set_level(DEBUG, ...) attaches caplog's own handler but does not stop records climbing to root — and at DEBUG, so even the steady-state events the eventlog design deliberately keeps below INFO got written out. The fixture now disables propagation for its duration and restores it after.

Guarding the NousResearch#69385 regression

Making the sandbox unconditional put an old regression back in reach by a new route. _capture_real_kanban_root() resolves via get_default_hermes_root(), which reads HERMES_HOME from the environment — now always rewired. Left alone, the kanban write-guard deny-list would have pointed at the throwaway tempdir and silently stopped protecting the operator's real ~/.hermes. It now restores the pre-sandbox value for the duration of that call, with a new guard test pinning it.

Verification

Positive control on the identical probe — pytest tests/agent/lsp/ tests/test_cli_skin_integration.py under HERMES_HOME=~/.hermes, same session, same environment:

tree bytes appended to real agent.log
unfixed (control) 4848
fixed 0

The control reproduced the reporter's exact fingerprint, including the synthetic roots and the /x*.py loop counter:

INFO hermes.lint.lsp: lsp[pyright] active for /private/var/folders/.../T/pytest-of-gary/pytest-282/test_reaper_survives_sweep_err0/repo
INFO hermes.lint.lsp: lsp[reaper] reaped 1 idle client(s) after 0s: pyright (/private/var/folders/.../repo)
INFO hermes.lint.lsp: lsp[pyright] 1 diags (/x0.py)

Other checks:

  • tests/agent/lsp/ — 61 passed (60 pre-existing + 1 new containment test); the dedup contract is unchanged.
  • tests/test_log_isolation.py — 4 passed (2 pre-existing + 2 new), including under a preset real HERMES_HOME, where it previously failed.
  • tests/hermes_cli/test_kanban_write_guard.py — 3 passed, both with and without a preset HERMES_HOME.
  • tests/test_hermetic_side_effect_guards.py, test_subprocess_home_isolation.py, test_profile_isolation_runtime.py, test_background_review_session_isolation.py — 31 passed.
  • ruff check clean on all three changed files.
  • Every file touched was also run unfixed vs fixed under per-file isolation with identical pass counts, so no pre-existing failure is attributable to this change.

Anti-criteria respected

  • Not fixed by filtering $TMPDIR at read time — that would leave the log corrupt for every other consumer and every future reader who does not know to filter. The writer is fixed.
  • hermes.lint.lsp production verbosity is untouched. Its INFO log_active / log_reaped lines are exactly what makes accumulation auditable.
  • No general hermes logging refactor.

Note on the reported timestamp skew

The reporter recorded polluting lines timestamped ahead of the wall clock and flagged the mechanism as unconfirmed. In my repro the skew was exactly 7h and is fully explained by the suite forcing TZ=UTC (the determinism invariant in conftest.py and scripts/run_tests.sh) while the gateway logs in local time. That accounts for my observation but not for their reported ~50-minute delta, so I am not claiming it as the general explanation. It does not affect the fix either way — the writer is fixed rather than time-windowed.

🤖 Generated with Claude Code

The LSP tests were writing language-server lifecycle records into
`~/.hermes/logs/agent.log`. That log is the only durable record of LSP
client lifecycle — gateway uptime is short, so a live `ps` snapshot
usually cannot answer "is LSP accumulation bounded" and the log is the
instrument. Replaying `log_active`/`log_reaped` pairs over the polluted
log reported 20 concurrent clients climbing with no balancing reaps;
filtering the synthetic `$TMPDIR` roots collapsed that to 7 with spawns
and reaps balanced exactly, against a ground truth of 0 live processes.
The pollution did not merely inflate a number, it inverted the verdict
that a build decision (an LRU cap) rested on.

Two independent causes, both closed here:

1. `tests/conftest.py` sandboxed HERMES_HOME only when it was unset. So
   the hole was open for exactly the people most likely to hit it —
   anyone running the suite from inside a Hermes agent or gateway
   process, where HERMES_HOME is exported and points at the real root.
   There the sandbox was skipped, import-time `setup_logging()` attached
   rotating handlers to the real agent.log, and every propagating logger
   in the suite wrote into it. The sandbox is now unconditional. With
   HERMES_HOME unset (CI and default local runs) behavior is unchanged:
   both paths create the same tempdir sandbox.

   `tests/test_log_isolation.py` already guarded this property and was
   genuinely failing under a preset HERMES_HOME; it now passes.

2. The `caplog_lsp` fixture called `caplog.set_level(DEBUG, ...)`, which
   attaches caplog's handler but leaves propagation on, so records still
   climbed to root — and at DEBUG, so even the steady-state events the
   eventlog design deliberately keeps below INFO were written out. The
   fixture now disables propagation for the duration and restores it.

Fixing the writer rather than filtering `$TMPDIR` at read time: the
latter would leave the log corrupt for every other consumer and every
future reader who does not know to filter. `hermes.lint.lsp` production
verbosity is untouched — its INFO `log_active`/`log_reaped` lines are
exactly what makes accumulation auditable.

Making the sandbox unconditional put the NousResearch#69385 kanban regression back
in reach by a new route: `_capture_real_kanban_root()` resolves via
`get_default_hermes_root()`, which reads HERMES_HOME from the
environment, which is now always rewired. It restores the pre-sandbox
value for the duration of that call so the deny-list keeps pointing at
the operator's real root. Covered by a new guard test.

Verified with a positive control on the identical probe
(`pytest tests/agent/lsp/ tests/test_cli_skin_integration.py` under
`HERMES_HOME=~/.hermes`): 4848 bytes appended to the real agent.log
before the fix, 0 bytes after.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 93c1991bd5

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".

Comment thread tests/agent/lsp/test_eventlog.py Outdated
pai-scaffolde and others added 2 commits August 9, 2026 02:09
Codex review on PR #61 flagged the `caplog_lsp` fixture as breaking
capture: pytest's `LogCaptureHandler` lives on the root logger, so
setting `hermes.lint.lsp.propagate = False` should cut these tests off
from their own records.

The predicted failure does not occur — the file passes 7/7 at
93c1991, and the claimed repro (`pytest -q tests/agent/lsp/test_eventlog.py`)
reproduces green. Under the pinned pytest 9.1.1,
`caplog.set_level(level, logger=...)` also binds the capture handler to
the named logger, so records are captured with propagation off.

The concern behind it is still fair: that binding is a pytest
implementation detail, not a documented promise, and the fixture was
silently depending on it. This makes the capture path explicit and
self-contained. It is a provable no-op today (pytest has already bound
the same handler object, so `attached_here` is False and neither
`addHandler` nor `removeHandler` runs) and becomes load-bearing only if
that behaviour changes. Teardown removes only a handler this fixture
added, leaving pytest's own handler lifecycle untouched.

Verified:
- tests/agent/lsp/test_eventlog.py     7 passed
- tests/test_log_isolation.py          4 passed
- tests/agent/lsp/                    61 passed
- anti-pollution control re-run under `HERMES_HOME=~/.hermes`
  (`pytest tests/agent/lsp/ tests/test_cli_skin_integration.py`):
  69 passed, 0 bytes appended to the real agent.log

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
test_sandbox_overrides_a_preset_hermes_home can only distinguish the
conditional sandbox from the unconditional one when HERMES_HOME is already
set at conftest import. Nothing in CI sets it, so with the conditional form
restored the `if not os.environ.get("HERMES_HOME")` branch is taken,
_SESSION_HERMES_HOME is bound anyway, and the guard passes on the exact code
it exists to reject.

Measured on this tree, reverting tests/conftest.py to the conditional form:

  HERMES_HOME preset  -> 2 failed, 2 passed   (guard fires)
  HERMES_HOME unset   -> 4 passed             (guard inert -- CI's case)

So the regression could be reintroduced and ship green.

Re-run the assertion in a child pytest that supplies the distinguishing
condition. Same revert now fails under CI conditions. The spawn is bounded
(timeout=300) so a wedged child fails the file instead of hanging a slice,
and a sentinel env var makes the spawning test skip itself in the child so
it cannot recurse.
pai-scaffolde added a commit that referenced this pull request Aug 20, 2026
… (SCA-4600) (#78)

* fix(tests): stop the suite writing into the operator's real agent.log

The LSP tests were writing language-server lifecycle records into
`~/.hermes/logs/agent.log`. That log is the only durable record of LSP
client lifecycle — gateway uptime is short, so a live `ps` snapshot
usually cannot answer "is LSP accumulation bounded" and the log is the
instrument. Replaying `log_active`/`log_reaped` pairs over the polluted
log reported 20 concurrent clients climbing with no balancing reaps;
filtering the synthetic `$TMPDIR` roots collapsed that to 7 with spawns
and reaps balanced exactly, against a ground truth of 0 live processes.
The pollution did not merely inflate a number, it inverted the verdict
that a build decision (an LRU cap) rested on.

Two independent causes, both closed here:

1. `tests/conftest.py` sandboxed HERMES_HOME only when it was unset. So
   the hole was open for exactly the people most likely to hit it —
   anyone running the suite from inside a Hermes agent or gateway
   process, where HERMES_HOME is exported and points at the real root.
   There the sandbox was skipped, import-time `setup_logging()` attached
   rotating handlers to the real agent.log, and every propagating logger
   in the suite wrote into it. The sandbox is now unconditional. With
   HERMES_HOME unset (CI and default local runs) behavior is unchanged:
   both paths create the same tempdir sandbox.

   `tests/test_log_isolation.py` already guarded this property and was
   genuinely failing under a preset HERMES_HOME; it now passes.

2. The `caplog_lsp` fixture called `caplog.set_level(DEBUG, ...)`, which
   attaches caplog's handler but leaves propagation on, so records still
   climbed to root — and at DEBUG, so even the steady-state events the
   eventlog design deliberately keeps below INFO were written out. The
   fixture now disables propagation for the duration and restores it.

Fixing the writer rather than filtering `$TMPDIR` at read time: the
latter would leave the log corrupt for every other consumer and every
future reader who does not know to filter. `hermes.lint.lsp` production
verbosity is untouched — its INFO `log_active`/`log_reaped` lines are
exactly what makes accumulation auditable.

Making the sandbox unconditional put the NousResearch#69385 kanban regression back
in reach by a new route: `_capture_real_kanban_root()` resolves via
`get_default_hermes_root()`, which reads HERMES_HOME from the
environment, which is now always rewired. It restores the pre-sandbox
value for the duration of that call so the deny-list keeps pointing at
the operator's real root. Covered by a new guard test.

Verified with a positive control on the identical probe
(`pytest tests/agent/lsp/ tests/test_cli_skin_integration.py` under
`HERMES_HOME=~/.hermes`): 4848 bytes appended to the real agent.log
before the fix, 0 bytes after.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* fix(tests): bind the capture handler explicitly in caplog_lsp

Codex review on PR #61 flagged the `caplog_lsp` fixture as breaking
capture: pytest's `LogCaptureHandler` lives on the root logger, so
setting `hermes.lint.lsp.propagate = False` should cut these tests off
from their own records.

The predicted failure does not occur — the file passes 7/7 at
93c1991, and the claimed repro (`pytest -q tests/agent/lsp/test_eventlog.py`)
reproduces green. Under the pinned pytest 9.1.1,
`caplog.set_level(level, logger=...)` also binds the capture handler to
the named logger, so records are captured with propagation off.

The concern behind it is still fair: that binding is a pytest
implementation detail, not a documented promise, and the fixture was
silently depending on it. This makes the capture path explicit and
self-contained. It is a provable no-op today (pytest has already bound
the same handler object, so `attached_here` is False and neither
`addHandler` nor `removeHandler` runs) and becomes load-bearing only if
that behaviour changes. Teardown removes only a handler this fixture
added, leaving pytest's own handler lifecycle untouched.

Verified:
- tests/agent/lsp/test_eventlog.py     7 passed
- tests/test_log_isolation.py          4 passed
- tests/agent/lsp/                    61 passed
- anti-pollution control re-run under `HERMES_HOME=~/.hermes`
  (`pytest tests/agent/lsp/ tests/test_cli_skin_integration.py`):
  69 passed, 0 bytes appended to the real agent.log

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* fix(tests): give the preset-HERMES_HOME guard teeth under CI

test_sandbox_overrides_a_preset_hermes_home can only distinguish the
conditional sandbox from the unconditional one when HERMES_HOME is already
set at conftest import. Nothing in CI sets it, so with the conditional form
restored the `if not os.environ.get("HERMES_HOME")` branch is taken,
_SESSION_HERMES_HOME is bound anyway, and the guard passes on the exact code
it exists to reject.

Measured on this tree, reverting tests/conftest.py to the conditional form:

  HERMES_HOME preset  -> 2 failed, 2 passed   (guard fires)
  HERMES_HOME unset   -> 4 passed             (guard inert -- CI's case)

So the regression could be reintroduced and ship green.

Re-run the assertion in a child pytest that supplies the distinguishing
condition. Same revert now fails under CI conditions. The spawn is bounded
(timeout=300) so a wedged child fails the file instead of hanging a slice,
and a sentinel env var makes the spawning test skip itself in the child so
it cannot recurse.

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
@pai-scaffolde

Copy link
Copy Markdown
Collaborator Author

Closing per principal decision 2026-08-20: superseded or abandoned (see landing ledger in scaffolde-ai .scaffolde/tasks/task-hermes-pr-backlog-landing/LEDGER.md). #61 superseded by merged #78; #70 superseded by merged #71 (sys.modules fix verified on main); #50/#51/#52/#58 abandoned SCA-4389 alternatives — #63's approach won and is landed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant