Skip to content

fix(cli): install the redacting excepthook for every subcommand, and report which tree answered --version (BACKLOG #1674, #1677) - #1201

Open
wshallwshall wants to merge 2 commits into
mainfrom
claude/b1674-1677-cli
Open

wshallwshall wants to merge 2 commits into
mainfrom
claude/b1674-1677-cli

Conversation

@wshallwshall

Copy link
Copy Markdown
Collaborator

Closes BACKLOG #1674 and #1677. One PR because both edit main() in messagefoundry/__main__.py and both add to tests/test_cli.py.

BACKLOG #1674 - the redacting last-resort excepthook was installed only by serve

messagefoundry/last_resort.py states the ASVS 16.5.4 guarantee that an unhandled error can never escape as a raw traceback that could quote a PHI-bearing value. That is a process property, but install_excepthook and install_thread_excepthook were called inside _serve, so the other 32 subcommands ran with the stock hooks. Both calls moved to the top of main().

The row's own reproduction no longer reproduces, and that is not evidence the row is closed

The row named audit-verify --db <directory> printing a sqlite3.OperationalError traceback. BACKLOG #1670 has since turned that into a clean line and exit 2, and test_audit_verify_exits_2_on_a_file_that_is_not_a_database pins it. Running the named repro now gives a clean result.

That fix covers one subcommand's handling of one exception class. It does not install the hook. So the tests probe the property instead:

  • test_a_non_serve_subcommand_installs_both_last_resort_hooks resets both hooks to the stdlib defaults, calls main(["hl7schema", "--json"]), and asserts both are the last_resort hooks afterwards. Restored in a finally, because pytest restores threading.excepthook per test but not sys.excepthook.
  • test_an_uncaught_exception_in_a_non_serve_subcommand_prints_no_traceback runs a child interpreter that swaps a _DISPATCH entry for a raiser, then asserts no Traceback on stderr and that the redacted last-resort line is there. A child is the only honest shape: sys.excepthook fires at the interpreter top level, which inside pytest never happens.

Why the hook-install shape and not the row's wrap-and-exit-2 alternative

Installing the hook changes no exit code. The interpreter still exits 1 once sys.excepthook returns, which the child-interpreter test asserts directly. The alternative would have turned four lines into an exit-code audit across 105 assertions, for no gain in the guarantee.

Both hooks, not one

install_thread_excepthook had the identical serve-only gap. sys.excepthook does not cover other threads: the interpreter routes a thread's escaping exception to threading.excepthook and nowhere else, and the engine's sandbox drain threads catch only OSError by design.

The import stays inside the function body

Two tests/test_config_anchoring.py monkeypatches (lines 262 and 376) target the module attribute messagefoundry.last_resort.install_excepthook. A module-scope import in __main__.py would bind the name before they can patch it and they would silently stop applying. Both still pass.

BACKLOG #1677 - --version now reports which tree answered

Two directories can supply messagefoundry/ to one interpreter and it picks silently. --version now prints the resolved package directory on its own second line.

A custom argparse.Action, not a newline in the version string

A newline inside action="version" does not produce a second line. argparse routes that text through HelpFormatter._fill_text, which re-wraps it into a single width-dependent paragraph, so the path lands mid-line at whatever column the terminal happens to be. Verified before writing the fix. Consequently the test asserts on the presence of the path token, never on a line index - a test keyed to lines[1] would pass on the author's terminal and be a coin flip elsewhere.

No new import: Path was already imported and __main__.py sits inside the package, so Path(__file__).resolve().parent is the package directory.

PYTHONSAFEPATH deliberately not set, and the row's claim about it is too strong

The row says review and CI instruments should set PYTHONSAFEPATH=1. Not done, and the docs note says why rather than repeating the claim:

  1. It removes the working directory from sys.path, which removes one of the two candidates. The venv's editable .pth target then wins unconditionally, and on a multi-worktree box that target can be a third checkout unrelated to both. It does not answer "which tree"; it changes which wrong answer you get silently.
  2. It would change nothing in CI anyway. Every leg installs editable from its own checkout, so the two candidates already agree.

The engine-side note is a docs/CI.md gotcha bullet carrying the action (run --version, record the line) and the correction above.

Out of scope: the vault review-plan paragraph

The row's closing act item 2 also asks for this to be recorded in the review plan. That document is vault-only and unreachable from an engine worktree, so it is not in this PR and remains open.

Findings that go beyond the brief

The asyncio loop handler has the same gap this PR just closed, for the third hook

Surfaced by the /simplify altitude pass and verified by hand. last_resort.py ships three hooks. This PR hoists two. The third, install_loop_exception_handler, is called from exactly one place - messagefoundry/api/app.py, inside the serving lifespan - yet nine subcommands call asyncio.run() and install nothing: supervise, admin-unlock, provision-admin, audit-verify, audit-anchor, rekey-audit, rotate-key, backup, restore-verify. Several of those open the store, which is the same class the row calls out as able to carry a field value.

Not built here, deliberately. It cannot be hoisted the same way (the handler needs a running loop, so it needs a wrapper at each asyncio.run() call site or a shared helper), it is a different shape from what #1674 describes, and a Builder should not widen a brief by guessing. Naming the subject rather than a number, since backlog numbers are not allocated in this repository: the asyncio loop exception handler is installed only by the serving lifespan, leaving nine asyncio.run() subcommands unguarded. Worth a row.

Smaller, same family: messagefoundry/support/bundle.py writes engine version into every support bundle without the package directory, so a bundle can reproduce the exact silent-wrong-tree failure #1677 fixes for --version.

A performance regression this PR introduced, found and fixed in the second commit

Putting the import in main() placed messagefoundry.last_resort on the fast introspection path. It imported asyncio at module scope for two functions only serve calls, and the package root does not load asyncio, so it was a net-new import on every subcommand.

Measured on Windows/3.14, marginal import cost with the root already loaded:

marginal cost modules added
before (module-scope asyncio) 30.3 / 31.8 / 40.2 ms full asyncio tree
after (TYPE_CHECKING + local import) 0.46 / 0.47 / 0.48 ms 1

Against the documented 335-399 ms budget for validate / hl7schema / lens schema. from __future__ import annotations keeps both signatures typed; mypy strict is clean.

One measurement trap recorded in the docstring because it is indistinguishable from the defect: the first import after editing the file recompiles the bytecode and reads 31.2 ms. My own first post-fix reading was exactly that artifact, and it looked like the fix had not worked. Warm the cache before believing any number here.

Checks run

All foreground, in this worktree's .venv, at e0d75fd0f.

  • /simplify - four review agents; findings applied in the second commit, skips noted below.
  • ruff check messagefoundry tests - clean.
  • ruff format --check over the repository - 1087 files already formatted.
  • mypy messagefoundry strict - clean, 275 source files.
  • pytest over every module that imports messagefoundry.__main__ or last_resort, in four batches: 1556 passed, 6 skipped, plus 291 and 333 on the re-run after the simplify pass. No failures at any point.
  • Each new test verified to fail with its own fix reverted, then restored. Reverting the main() install failed both #1674 tests; reverting to action="version" failed the #1677 test.

Local runs report INCOMPLETE RUN -- coverage was NOT collected because the vault extra is absent from this interpreter. Expected; naming it rather than reporting a green that does not cover those modules.

/simplify findings applied

  • asyncio off the module-scope import path (above).
  • SDS-3.5: the sys.path shadowing mechanism was stated three times. Now stated once on _VersionAction, with docs/CI.md and the test docstring pointing at it.
  • An assert "messagefoundry" in out that the path assertion below it already subsumed, replaced with one on the version string, which is independent.
  • The note left in _serve trimmed from "used to be here" narration to the live invariant.

/simplify findings skipped, and why

  • Factor the excepthook stash/restore into a shared fixture (third occurrence, counting tests/test_last_resort.py). Its home would be tests/conftest.py, which a sibling Builder holds for BACKLOG #1304. Not worth a collision for a three-line try/finally.
  • A shared "run the CLI in a child interpreter" test helper. The two call sites differ in what they run (-m messagefoundry versus a driver script); the shared part is one subprocess.run.
  • Give _VersionAction an __init__ baking in nargs=0 and default=argparse.SUPPRESS. Correct that the stdlib does it that way, but it adds more lines than it removes for a class registered once, and the explicit call site is self-documenting.

CI legs a reader must check after my process exits

  • test on Windows and Linux - the three new tests live in the existing tests/test_cli.py, so no new job and no new matrix leg. One of them spawns a child interpreter, which adds roughly a second to an existing job.
  • step_margin - the test step gets slightly longer; it should stay far inside its cap, but it is the leg that would notice.
  • windows-service-smoke - never visible to a Builder. main() now installs process hooks before dispatch, and service is a dispatched subcommand, so this is the leg that would show an interaction with NSSM if there is one.
  • Anything asserting on CLI exit codes. Exit codes are unchanged by construction and 1556 local tests agree, but this is the claim to disbelieve first if something reds.

Proposed ledger banner text

Not applied here - docs/BACKLOG.md in this repository is a 23-line public stub and the ledger is vault-only, so this PR does not touch it.

#1674:

Closed DATE by PR N. install_excepthook and install_thread_excepthook moved from _serve to the top of main(), so the ASVS 16.5.4 guarantee holds for all 33 subcommands. The row's audit-verify --db <directory> repro no longer reproduces - BACKLOG #1670 fixed that path - so the tests probe the property (is the hook installed for a non-serve subcommand, and does an uncaught exception in one print no traceback) rather than the stale repro. The hook-install shape was taken over the row's wrap-and-exit-2 alternative: installing a hook changes no exit code, so the guarantee is met without an exit-code audit across 105 assertions. Sibling gap left open and unfiled: the third hook, the asyncio loop exception handler, is still installed only by the serving lifespan, while nine subcommands call asyncio.run().

#1677:

Closed DATE by PR N. --version prints the resolved package directory on its own second line, via a custom argparse.Action - action="version" re-wraps an embedded newline through HelpFormatter._fill_text into one width-dependent paragraph, so the test asserts on the path token and never on a line index. Closing act item 2 is split: the docs/CI.md note landed, the vault review-plan paragraph is out of reach from an engine worktree and stays open. The row's PYTHONSAFEPATH=1 prescription was deliberately not adopted and the docs note records why: it removes only the cwd candidate and lets the editable .pth target win unconditionally, which on a multi-worktree box can be a third unrelated checkout, and it would change nothing in CI where every leg installs editable from its own checkout.

wshallwshall added 2 commits September 16, 2026 13:00
…report which tree answered --version (BACKLOG #1674, #1677)

#1674 -- `last_resort` states the ASVS 16.5.4 guarantee that an unhandled error
can never escape as a raw traceback quoting a PHI-bearing value. That guarantee
is a process property, but `install_excepthook` and `install_thread_excepthook`
were called inside `_serve`, so the other 32 subcommands ran unguarded. Move
both calls to the top of `main()`.

The row's own reproduction no longer reproduces: BACKLOG #1670 turned
`audit-verify --db <directory>` into a clean line and exit 2. That fix covers
one subcommand and one exception class, not the process-wide guarantee, so the
tests probe the property (is the hook installed for a non-serve subcommand)
rather than re-running the stale repro.

Installing the hook changes no exit code -- the interpreter still exits 1 once
`sys.excepthook` returns -- which is why this shape was taken over the row's
alternative of wrapping the dispatch and exiting 2. That alternative would have
reopened every CLI exit-code assertion in the suite.

The import stays inside the function body: two `tests/test_config_anchoring.py`
monkeypatches target the module attribute, and a module-scope import would bind
the name before they can patch it.

#1677 -- the working directory precedes the venv's editable `.pth` entry on
`sys.path`, so running from a directory holding another copy of the package
imports that copy, silently. `--version` now prints the resolved package
directory on its own second line.

A custom `argparse.Action`, not a newline inside `action="version"`: argparse
re-wraps that text through `HelpFormatter._fill_text` into one width-dependent
paragraph, so the newline is collapsed and the path lands mid-line. The test
therefore asserts on the presence of the path token, never on a line index.

`PYTHONSAFEPATH=1` is deliberately not set across the workflows. It removes the
working directory from `sys.path`, which removes one candidate and lets the
`.pth` target win unconditionally -- on a multi-worktree box that target can be a
third checkout unrelated to either. It would also change nothing in CI, where
every leg installs editable from its own checkout. `docs/CI.md` records both
halves.
…now pays

Follow-up to the commit before it, from the /simplify pass.

Moving the excepthook install into `main()` put `messagefoundry.last_resort` on
the fast introspection path (`validate`, `hl7schema`, `lens schema`) that
`__main__`'s docstring promises to keep cheap. That module imported `asyncio` at
scope for two functions only `serve` ever calls, and the package root does not
load `asyncio`, so it was a net-new import on every subcommand.

Measured on Windows/3.14, marginal import cost with the root already loaded:
30.3 / 31.8 / 40.2 ms before, 0.46 / 0.47 / 0.48 ms after -- one module added
instead of the whole asyncio tree, against a documented 335-399 ms budget for
those subcommands. `from __future__ import annotations` plus a `TYPE_CHECKING`
import keeps both signatures typed; mypy strict is clean.

The first measurement after editing the file read 31.2 ms, which is bytecode
recompilation and not the regression. The docstring says so, because the artifact
is indistinguishable from the defect.

Also from the same pass:
- state the sys.path shadowing mechanism once, on `_VersionAction`, and point
  `docs/CI.md` and the test docstring at it rather than restating it (SDS-3.5).
- replace a `"messagefoundry" in out` assertion that the path assertion below it
  already subsumed with one on the version string, which is independent.
- trim the note left in `_serve` to the live invariant.
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

Lander review

Verified before reviewing: release.yml has zero mentions in the diff, and asyncio is imported at lines 28 and 63 of last_resort.py indented — function-local, which is the regression fix rather than the defect.

The regression it introduced and caught is the better half of this PR

Hoisting the import put asyncio at module scope in last_resort.py, which the package root does not import — 30-40 ms on every fast subcommand. Found by the efficiency pass, not by review, and removed in a second commit: 30.3 / 31.8 / 40.2 down to 0.46 / 0.47 / 0.48.

A fix that quietly taxes every CLI invocation is exactly the kind that ships, because nothing fails.

The measurement trap is the thing I want on the record

Its first post-fix reading was 31.2 ms and looked like the fix had not worked. That was bytecode recompilation from its own edit, not the defect — and the two are indistinguishable in a single reading.

A session trusting that would have reverted a correct fix. That is the same class as everything else measured today — an instrument returning a number to a question nobody asked — but it is the first instance where the wrong reading would have destroyed working code rather than merely misinformed. Recording it in the docstring is right; the PR body would not be in front of the next person to measure.

It probed the property rather than re-running the stale repro

Reset both hooks to stdlib defaults, call a non-serve subcommand, assert both are the last_resort hooks — plus a child-interpreter test that an uncaught exception in a non-serve subcommand prints no traceback. All three verified to fail with their own fix reverted, then restored.

Not re-running #1674's own repro is the correct instinct: a row's repro proves the row's framing, and the framing is what had a third instance it never named.

The third instance is real and I will file it

install_loop_exception_handler is called from exactly one place, api/app.py:5890, the serving lifespan — while __main__.py carries 8 asyncio.run( call sites across supervise, admin-unlock, provision-admin, audit-verify, audit-anchor, rekey-audit, rotate-key, backup and restore-verify. The sync and thread hooks are now hoisted and cover all 33 subcommands; the loop handler cannot be hoisted the same way because it needs a running loop.

Deliberately not built, named as a subject rather than a number. That is the right call and the right disclosure — and the 9-subcommands-against-8-grep-hits discrepancy is stated rather than smoothed, which is what lets a reader check it.

Legs to read after the fact

test on both platforms, step_margin, and windows-service-smokeservice is now a dispatched subcommand running under the new hooks and no Builder sees that leg.

Verdict: merge.

@github-actions github-actions Bot added the ci-red A required check went red. Attribute it before retrying. label Sep 16, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ci-red A required check went red. Attribute it before retrying.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant