fix(cli): install the redacting excepthook for every subcommand, and report which tree answered --version (BACKLOG #1674, #1677) - #1201
wshallwshall wants to merge 2 commits into
Conversation
…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.
Lander reviewVerified before reviewing: The regression it introduced and caught is the better half of this PRHoisting the import put 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
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 reproReset both hooks to stdlib defaults, call a non-serve subcommand, assert both are the 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
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
Verdict: merge. |
Closes BACKLOG #1674 and #1677. One PR because both edit
main()inmessagefoundry/__main__.pyand both add totests/test_cli.py.BACKLOG #1674 - the redacting last-resort excepthook was installed only by
servemessagefoundry/last_resort.pystates 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, butinstall_excepthookandinstall_thread_excepthookwere called inside_serve, so the other 32 subcommands ran with the stock hooks. Both calls moved to the top ofmain().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 asqlite3.OperationalErrortraceback. BACKLOG #1670 has since turned that into a clean line and exit 2, andtest_audit_verify_exits_2_on_a_file_that_is_not_a_databasepins 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_hooksresets both hooks to the stdlib defaults, callsmain(["hl7schema", "--json"]), and asserts both are thelast_resorthooks afterwards. Restored in afinally, because pytest restoresthreading.excepthookper test but notsys.excepthook.test_an_uncaught_exception_in_a_non_serve_subcommand_prints_no_tracebackruns a child interpreter that swaps a_DISPATCHentry for a raiser, then asserts noTracebackon stderr and that the redacted last-resort line is there. A child is the only honest shape:sys.excepthookfires 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.excepthookreturns, 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_excepthookhad the identical serve-only gap.sys.excepthookdoes not cover other threads: the interpreter routes a thread's escaping exception tothreading.excepthookand nowhere else, and the engine's sandbox drain threads catch onlyOSErrorby design.The import stays inside the function body
Two
tests/test_config_anchoring.pymonkeypatches (lines 262 and 376) target the module attributemessagefoundry.last_resort.install_excepthook. A module-scope import in__main__.pywould bind the name before they can patch it and they would silently stop applying. Both still pass.BACKLOG #1677 -
--versionnow reports which tree answeredTwo directories can supply
messagefoundry/to one interpreter and it picks silently.--versionnow prints the resolved package directory on its own second line.A custom
argparse.Action, not a newline in the version stringA newline inside
action="version"does not produce a second line. argparse routes that text throughHelpFormatter._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 tolines[1]would pass on the author's terminal and be a coin flip elsewhere.No new import:
Pathwas already imported and__main__.pysits inside the package, soPath(__file__).resolve().parentis the package directory.PYTHONSAFEPATHdeliberately not set, and the row's claim about it is too strongThe row says review and CI instruments should set
PYTHONSAFEPATH=1. Not done, and the docs note says why rather than repeating the claim:sys.path, which removes one of the two candidates. The venv's editable.pthtarget 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.The engine-side note is a
docs/CI.mdgotcha 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
/simplifyaltitude pass and verified by hand.last_resort.pyships 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 callasyncio.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 nineasyncio.run()subcommands unguarded. Worth a row.Smaller, same family:
messagefoundry/support/bundle.pywrites 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()placedmessagefoundry.last_resorton the fast introspection path. It importedasyncioat module scope for two functions onlyservecalls, and the package root does not loadasyncio, so it was a net-new import on every subcommand.Measured on Windows/3.14, marginal import cost with the root already loaded:
asyncio)TYPE_CHECKING+ local import)Against the documented 335-399 ms budget for
validate/hl7schema/lens schema.from __future__ import annotationskeeps 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, ate0d75fd0f./simplify- four review agents; findings applied in the second commit, skips noted below.ruff check messagefoundry tests- clean.ruff format --checkover the repository - 1087 files already formatted.mypy messagefoundrystrict - clean, 275 source files.pytestover every module that importsmessagefoundry.__main__orlast_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.main()install failed both #1674 tests; reverting toaction="version"failed the #1677 test.Local runs report
INCOMPLETE RUN -- coverage was NOT collectedbecause thevaultextra is absent from this interpreter. Expected; naming it rather than reporting a green that does not cover those modules./simplifyfindings appliedasynciooff the module-scope import path (above).sys.pathshadowing mechanism was stated three times. Now stated once on_VersionAction, withdocs/CI.mdand the test docstring pointing at it.assert "messagefoundry" in outthat the path assertion below it already subsumed, replaced with one on the version string, which is independent._servetrimmed from "used to be here" narration to the live invariant./simplifyfindings skipped, and whytests/test_last_resort.py). Its home would betests/conftest.py, which a sibling Builder holds for BACKLOG #1304. Not worth a collision for a three-linetry/finally.-m messagefoundryversus a driver script); the shared part is onesubprocess.run._VersionActionan__init__baking innargs=0anddefault=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
teston Windows and Linux - the three new tests live in the existingtests/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- theteststep 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, andserviceis a dispatched subcommand, so this is the leg that would show an interaction with NSSM if there is one.Proposed ledger banner text
Not applied here -
docs/BACKLOG.mdin this repository is a 23-line public stub and the ledger is vault-only, so this PR does not touch it.#1674:
#1677: