From 04f956fd7904068e5a181238feb0e317c43a676e Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 17:37:24 -0500 Subject: [PATCH 01/16] docs(adr): ADR 0166 -- sandbox child stderr captured and relayed, content below INFO (BACKLOG #343) Records the design decision for #343 before the engine change lands, because the diff shows what and never why, and the why here is a rejection that is easy to re-litigate. THE REJECTED ALTERNATIVE IS THE LOAD-BEARING PART. Relaying child stderr at INFO with a per-line byte cap is the obvious compromise and it fails on the shape of this payload specifically: truncating an HL7 v2 message to its first N bytes keeps MSH and PID -- the header and the patient identifying segment -- and discards the clinically bulky remainder. A byte cap therefore preserves precisely the most identifying part of the record. It is the worst available redaction for this format, not merely a weak one, and it would place a CLAUDE.md section 9 violation inside the fix for the defect that violation is about. So content relays at DEBUG only, and INFO and above get an attributed rate-limited notice carrying identity and a count and no content. That satisfies section 9 BY CONSTRUCTION rather than by operator discipline: no call site above DEBUG carries content. States the hazard the decision CREATES rather than softening it: stderr=PIPE with no drainer blocks a flooding child, and the window that matters is bootstrap, where load_config() runs untrusted admin code before the boot reply is read. The stderr reader must start in the same window the stdout reader does. Findings are written conditionally per CLAUDE.md section 0 -- zero deployments, so a deploying site WOULD inherit this on first deployment; nothing is exposed today. Index row added in the same commit, as the ledger gate requires. ADR number allocated by this worktree via alloc.ps1 -- ownership is keyed on the committing worktree and is non-transferable. --- ...captured-and-relayed-content-below-info.md | 118 ++++++++++++++++++ docs/adr/README.md | 1 + 2 files changed, 119 insertions(+) create mode 100644 docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md diff --git a/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md b/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md new file mode 100644 index 000000000..414828b22 --- /dev/null +++ b/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md @@ -0,0 +1,118 @@ +# ADR 0176 — Sandbox child stderr is captured and relayed, with content confined below INFO + +- **Status:** **Proposed (2026-08-14)** — records the design decision for BACKLOG #343. The engine + change is being built against it; this file is the *why*, which the diff cannot carry. + +- **Date:** 2026-08-14 +- **Supersedes nothing.** Extends the fd-discipline established for the sandbox IPC channel in + [ADR 0087](0087-sandbox-subprocess-isolation.md) to the one file descriptor that decision left + undisciplined. + +## Context + +**fd 1 is strictly framed. fd 2 has no discipline at all.** The sandbox worker is spawned at +[`pipeline/sandbox.py:442-450`](../../messagefoundry/pipeline/sandbox.py) with `stdout=PIPE` and +`stderr=None`. The `None` is load-bearing and was deliberate — its comment reads *"let the child's +stderr (logging) pass through to the engine's stderr"* — but the consequence is that the child's +stderr **is** the engine's own stderr, inherited raw. Admin-authored Handler code therefore writes +directly into the engine's log stream, unframed and unattributed. + +**Two problems live in that one fact, and they have different severities and different fixes.** + +**(a) Attribution.** A line emitted by a sandboxed Handler is byte-indistinguishable from a line +emitted by the engine. An operator reading the log cannot tell which inbound produced it, and a +Handler can therefore forge engine log lines, emit ANSI control sequences, or write content that +breaks whatever consumes the log. The service runs under NSSM, which captures stdout and stderr to +files ([docs/SERVICE.md](../SERVICE.md)), so the forged line lands in the operator's log of record. + +**(b) PHI, and this is the half that matters.** A Handler that calls `print()` on a message body +writes a **full payload** into the general log at whatever level the operator is running. +[CLAUDE.md](../../CLAUDE.md) section 9 forbids logging full message bodies at INFO or above. Nothing +in the current path can prevent this, because there is no path — the bytes are not passing through +any code the engine controls. + +**Both are conditional, not live.** MessageFoundry has zero deployments +([CLAUDE.md](../../CLAUDE.md) section 0), so nothing is exposing anything today. The correct framing +is that a deploying site **would** inherit both on first deployment. That changes the wording of the +finding and not one thing about the fix: these rules exist so the first deployment is safe. + +**An adjacent defect shares the root and is closed here rather than left.** A Handler that `print()`s +to **stdout** lands in the interpreter's `TextIOWrapper` buffer, while the IPC frames are written +through the underlying `BufferedWriter`. The two do not currently interleave badly, so frames are not +corrupted today. **That is luck, not design** — it depends on buffering behaviour nobody chose and +nothing pins. Leaving it is leaving a latent frame corruption behind a coincidence. + +## Decision + +**D1 — Capture the child's stderr and relay it through the engine's stdlib logger.** Spawn with +`stderr=subprocess.PIPE` and drain it on a dedicated reader thread, mirroring the existing stdout +frame reader at [`sandbox.py:495`](../../messagefoundry/pipeline/sandbox.py). Every relayed line is +attributed to the inbound and worker that produced it, sanitised of ANSI and other control bytes, and +rate-limited, with the suppression count reported rather than silently dropped. + +**D2 — Content is relayed at DEBUG only. At INFO and above, the engine emits an attributed, +rate-limited NOTICE carrying the identity and a count, and no content.** This is the load-bearing +clause. It satisfies section 9 **by construction** rather than by operator discipline: there is no +configuration, no verbosity setting and no error path by which child stderr content reaches a log +record at INFO or above, because no such call site exists. An operator running at INFO still learns +*that* a given inbound's Handler is writing to stderr, and how much, which is the operationally +actionable part. + +**D3 — The worker rebinds `sys.stdout` to fd 2 at bootstrap, leaving raw fd 1 exclusively for +frames.** Sequenced after the frame writer captures its raw handle and before `load_config()` runs +any admin-authored code — which the comment at +[`sandbox.py:452-455`](../../messagefoundry/pipeline/sandbox.py) already identifies as the earliest +untrusted code and the first opportunity to spawn a grandchild. + +## Alternatives rejected + +**Relay at INFO with a per-line byte cap — rejected, and the reason generalises.** This is the +obvious compromise: keep the diagnostics visible at normal verbosity, bound the leak with a +truncation. It fails on the specific shape of this payload. **Truncating an HL7 v2 message to its +first N bytes keeps MSH and PID** — the message header and the patient identifying segment — and +discards the clinically bulky remainder. A byte cap therefore preserves *precisely* the most +identifying part of the record and throws away the least sensitive. It is the **worst available +redaction for this format**, not merely a weak one, and it would put a section 9 violation inside the +fix for the defect that violation is about. A truncated body is still PHI. + +**`stderr=subprocess.DEVNULL` — rejected.** It closes both problems completely and costs the +operator every Handler traceback. A sandboxed Handler that crashes would fail silently, which trades +a log-integrity defect for a diagnosability one. + +**Leave `stderr=None` and document the hazard — rejected.** The threat model is admin-authored +config, which is the same trust boundary ADR 0087 built the sandbox to contain. A control that exists +only as prose in a document is the compensating-control-on-a-false-premise shape that +[CLAUDE.md](../../CLAUDE.md) section 11 (SDS-3.7) forbids. + +## Consequences + +**A deadlock hazard is CREATED by this change and must be closed in the same commit.** With +`stderr=None` a flooding child is harmless, because the bytes go straight to the inherited descriptor. +With `stderr=PIPE` and nobody draining, a child that fills the pipe buffer **blocks**. The window that +matters is bootstrap: `load_config()` runs untrusted admin code before the boot reply is read, so a +child that writes enough to stderr during config load would hang until `startup_seconds` expires. The +stderr reader must therefore start in the same window the stdout reader does — before the boot frame +write — and no spawn or error path may leave a `PIPE` undrained. **This hazard did not exist before +this decision.** + +**Attribution requires plumbing the engine does not have today.** `SandboxRunner` holds its policy, +config directory and environment, but no inbound name. Attributing a relayed line to an inbound +therefore widens the change beyond `sandbox.py` into the construction site in `engine.py`. That cost +is accepted: an unattributed relay closes (b) and leaves (a) open, and (a) is the forgery half. + +**A second reader thread is a second teardown obligation.** It must be daemonised, cooperatively +stopped, and torn down on respawn and on close alongside the existing reader, or a killed worker +generation leaks a thread holding a dead pipe. + +**Operators running at INFO lose Handler stdout and stderr content.** This is the deliberate cost of +D2 and should be stated in the operator documentation rather than discovered. The notice tells them +the content exists and at which level to find it. + +## References + +- BACKLOG #343 — the filed defect, from an adversarial review of the ADR 0087 sandbox codec. +- [ADR 0087](0087-sandbox-subprocess-isolation.md) — the sandbox and its fd 1 framing contract. +- [CLAUDE.md](../../CLAUDE.md) section 9 and [docs/PHI.md](../PHI.md) — the PHI logging rule this + decision satisfies by construction. +- [CLAUDE.md](../../CLAUDE.md) section 0 — why the finding is written conditionally. +- [docs/SERVICE.md](../SERVICE.md) — NSSM capturing stdout and stderr to the operator's log files. diff --git a/docs/adr/README.md b/docs/adr/README.md index 55421f6ce..ac120668e 100644 --- a/docs/adr/README.md +++ b/docs/adr/README.md @@ -195,3 +195,4 @@ what is withheld and what you can request. | [0170](0170-constant-work-recovery-code-verification-pad-to-the-configured-slot-count-rather-than-short-circuit.md) | **Constant-work recovery-code verification: pad to the configured slot count rather than short-circuit** (BACKLOG #1167, ASVS 11.2.4) -- `_verify_second_factor` walked the argon2id recovery-code hashes and `return`ed on the first match, so the NUMBER of ~64 MiB verifications was a function of which code was presented. **Two leaks and only one matters:** the matched INDEX is worthless (the attacker holds the code and the response answers them anyway), but on the FAILURE path the cost is one verify per REMAINING code -- so anyone holding the password can time a wrong-code refusal and learn how many recovery codes an account has left, without authenticating to the second factor. **The item rated this difficulty 7 on a premise that does not survive measurement:** the re-score says a constant loop 'converts a timing leak into a memory and CPU amplification target', which is the right objection to raise -- and the failure path ALREADY verifies every remaining hash, so making the walk unconditional introduces no new cost, it makes today's WORST CASE the only case. Decision: always run exactly `mfa_recovery_code_count` verifies, padding with the same fixed `_DUMMY_PASSWORD_HASH` the local login leg uses, and select the winner AFTER the loop. Ceiling unmoved (default 10, validator-capped 50); `_argon2`'s semaphore means the concurrent-argon2 footprint cannot widen either; and the path sits behind primary authentication, so it is not an unauthenticated flood surface. **Claims constant WORK, not constant TIME** -- the store round trip on a match is not equalized, the TOTP branch returns earlier, and argon2's own constant-timeness is INHERITED from `argon2-cffi` and has never been measured in this tree, a gap #1167 names and this does not close. No timing measurement was run by the item or by this change. Rejected: leaving the short-circuit as accepted (the fix cost nothing against the existing ceiling, so 'accepted' would have been a judgement made before the amplification premise was checked); and a non-secret lookup index so only ONE verify ever runs -- strictly better on both axes, rejected as OUT OF SCOPE rather than wrong, needing a schema change across three backends and a migration, and recorded so it is not re-derived if the constant walk's cost ever bites | **Accepted (2026-08-22)** -- built with the change. Three parametrized tests pin the count for a first-slot match, a last-slot match and a non-match; proven red-first, removing the padding reds ALL THREE and the file restores byte-identical by SHA-256. Severity conditional per CLAUDE.md section 0 -- **zero deployments**, so this is what a first deployment would have inherited | | [0171](0171-offline-administrator-unlock-a-host-gated-cli-recovery-path-for-a-sole-administrator-lockout.md) | **Offline administrator unlock: a host-gated CLI recovery path for a sole-administrator lockout** (BACKLOG #1236) -- a deployment with ONE administrator had no recovery from account lockout, and every exit is individually deliberate: the bootstrap account is literally `admin`, it is created with no email so the ACCOUNT_LOCKED notice never leaves the process, self-reset is refused, an admin reset needs ANOTHER admin, re-bootstrap fires only on an EMPTY users table, and none of 38 CLI subcommands managed users. **The defect is that they close SIMULTANEOUSLY for that deployment** and nothing notices the conjunction. **The filed acceptance criterion could not discriminate and was amended 2026-08-21:** "recover without hand-editing the database and without a second admin" PASSES ON THE SHIPPED SYSTEM BY WAITING, since the lock self-expires after `lockout_minutes`; a test both a fixed and a broken system pass is not a test. Decision: `messagefoundry admin-unlock --username `. **The gate is HOST ACCESS and it is a real gate rather than an absent one** -- reaching it needs the config, the store path and on an encrypted store the key material, so anyone holding all three already has the database and does not need an unlock to reach an account; that is why it ships unauthenticated, and it is the load-bearing claim. **Clears the lockout and does NOT reset the password** -- deliberately narrower, since a reset would hand the runner a working account. **Reuses `record_login_failure(failed_attempts=0, locked_until=None)` rather than adding a protocol method**, decided by a MEASURED cross-lane fact rather than taste: a named `clear_lockout` would touch base/store/postgres/sqlserver, and all four were uncommitted in a peer lane at the time, so reuse avoided a four-file collision. Exit codes follow the `--json` convention (`_emit_error`, 1) not the M-31 lineage (stderr, 2), verified against `audit-verify` which has no `--json` flag. Carries M-31 forward: a typo'd `--db` is refused rather than creating an empty SQLite store and reporting a false "no such account" | **Accepted (2026-08-22)** -- built with the change. Four tests; **exactly ONE is the control** and the other three are deliberately insensitive -- neutering the clearing call reds only the acceptance test, and the audit-row test still passes under that plant, so it evidences the flow RAN and never that it WORKED. Does NOT address #1236's repetition limb: lock cycles remain unbounded and an attacker can re-lock. Severity conditional per CLAUDE.md section 0 -- **zero deployments** | | [0173](0173-tls-peer-revocation-checking-and-ocsp-stapling-across-terminating-and-originating-surfaces.md) | **TLS peer revocation checking and OCSP stapling across terminating and originating surfaces** (BACKLOG #1005, ASVS 12.1.4) -- the requirement reaches in two directions and the engine answers neither: where the product TERMINATES TLS it does not staple its own certificate's status, and where it ORIGINATES it does not check the peer's revocation. Direction 1 is RUNTIME-BLOCKED rather than unbuilt -- CPython 3.14.6 exposes no stapling surface at all, measured against live positive controls, so no amount of engineering here reaches it. The opt-in client-certificate CRL checking that DOES ship (`config/tls_policy.py:215-276`, three PROTOCOL_TLS_SERVER call sites) is a THIRD combination -- peer revocation on the terminating side -- and moves neither graded direction; that is the single easiest thing in this area to misread. DECISION: accept and document both directions, with one build rider the accept reasoning does not cover -- three originating hops that never reach the existing revocation guard, filed by subject and deliberately unallocated. | **Proposed (2026-08-23)** -- no code changed. Severity is conditional per CLAUDE.md section 0: on a first deployment a revoked partner certificate would keep verifying on the unguarded hops; there are zero deployments today. Five citation errors from the adversarial pass were repaired before filing. | +| [0176](0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md) | **Sandbox child stderr is captured and relayed, with content confined below INFO** (BACKLOG #343) — the sandbox worker is spawned with `stderr=None` (`pipeline/sandbox.py:446`), so **fd 1 is strictly framed and fd 2 has no discipline at all**: the child's stderr *is* the engine's stderr, inherited raw, and admin-authored Handler code writes straight into the operator's log of record (NSSM captures it to files). Two problems with different severities live in that one fact — **(a) attribution**, a Handler line being byte-indistinguishable from an engine line, hence forgeable log lines and ANSI control sequences; and **(b) PHI**, a Handler `print()`ing a message body writing a full payload into the general log, which CLAUDE.md section 9 forbids at INFO and above. Both are **conditional, not live** (section 0: zero deployments) — a deploying site would inherit them on first deployment. **Decision:** capture with `stderr=PIPE` and relay on a dedicated reader thread mirroring the existing frame reader, attributed, ANSI-sanitised and rate-limited with the suppression count reported; **relay CONTENT at DEBUG only, and at INFO and above emit an attributed rate-limited NOTICE carrying identity and a count and no content**, which satisfies section 9 **by construction** rather than by operator discipline because no INFO-or-above call site carrying content exists; and rebind the worker's `sys.stdout` to fd 2 at bootstrap, after the frame writer captures its raw handle and before `load_config()` runs untrusted code, closing the adjacent latent frame corruption that survives today **by buffering luck rather than design**. **The rejected alternative is the instructive one: relay at INFO with a per-line byte cap.** It fails on the shape of this payload specifically — **truncating an HL7 v2 message to its first N bytes keeps MSH and PID**, the header and the patient identifying segment, discarding the clinically bulky remainder, so a byte cap preserves *precisely* the most identifying part. It is the **worst available redaction for this format**, not merely a weak one, and would place a section 9 violation inside the fix for the defect that violation is about. Also rejected: `DEVNULL` (closes both problems, costs every Handler traceback) and prose-only documentation (a compensating control resting on nothing, the SDS-3.7 shape). **Consequence stated rather than softened: this decision CREATES a deadlock hazard that did not previously exist** — `stderr=PIPE` with no drainer blocks a flooding child, and the window that matters is bootstrap, where `load_config()` runs untrusted code before the boot reply is read, so the stderr reader must start in the same window the stdout reader does and no error or respawn path may leave a PIPE undrained. Attribution also **widens the diff beyond `sandbox.py`**: `SandboxRunner` holds no inbound identity today, so it must be plumbed from `engine.py` — accepted, because an unattributed relay closes (b) and leaves (a), the forgery half, open | **Proposed (2026-08-14)** — engine change being built against it under BACKLOG #343 | From 2eed70cbc4cf5a407e9f878c15a0a2cec5da487a Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 18:01:45 -0500 Subject: [PATCH 02/16] feat(worktree): install receipts for the machine-global gate, and refuse a silent overwrite (BACKLOG #1247) The installed gate's content changed on this box while three sessions ran against it, and afterwards nobody could say who wrote it. The change was benign -- it moved the gate forward -- which is not the point: an unattributable write to a shared safety control is the same class of event whichever direction it moves the file. FOUR MECHANISMS COULD HAVE RECORDED IT AND NONE WAS PRESENT: no backup, no receipt, no log line, and no usable timestamp. The install site was a bare Copy-Item. THE MTIME WAS THE TRAP, NOT THE GAP, and this does not repair it. Copy-Item carries the SOURCE's LastWriteTime, so the installed copy inherits an mtime from whichever checkout installed it. A correct stale-gate report was RETRACTED on the strength of one, and the retraction reached three sessions and the owner before a baseline hash reproved the original finding. An absent record makes a reader say "unknown"; a WRONG record makes them say something false with confidence. A corrected timestamp would still be one mutable field asserting a fact nothing corroborates, so the record is the receipt. PROVENANCE IS THREE-WAY AND COLLAPSING IT TO A BOOLEAN LOSES THE POINT. UNRECORDED (a gate installed before this change) is the normal first-run state and must NOT be fatal -- refusing there would block the very re-install that adopts the mechanism. Only MODIFIED stops the install, because an overwrite destroys the only evidence that anything happened. -OverwriteUnverifiedGate proceeds deliberately. THE HELPER IS A SEPARATE FILE FOR A TESTABILITY REASON, not a stylistic one: install-gate.ps1 cannot be dot-sourced to reach its functions, because loading it performs a machine-global install into ~/.claude. A suite that had to install the gate to test the receipt would be a suite that installs the gate, and that is the owner's action by design. IT REUSES Get-GateHash RATHER THAN HASHING AFRESH. That digest folds CRLF, because git stores LF and a Windows checkout carries CRLF; a second basis would let the receipt and tests/test_gate_installed_parity.py disagree about one file. A DEFECT FOUND WHILE BUILDING THIS, RECORDED IN THE CODE BECAUSE IT IS THE SAME CLASS THE ITEM IS ABOUT: try is not an expression in PowerShell. Written as a parenthesised try/catch in a hashtable value, the parser reads try as a command name, ParseFile reports the file CLEAN, and at run time it discards the whole hashtable, writes a receipt containing the literal null, and still returns a path and exits 0. The round-trip guard did not catch it either, because null is valid JSON -- a check its own failure mode satisfies is not a check. Both are now fixed and commented. Tests split deliberately: behaviour against a temp directory (never the real gate), plus static assertions that the installer is WIRED to call it. Each half is blind to the other's failure -- the behavioural tests pass if nothing calls the functions, the static ones pass if every function is wrong. --- scripts/worktree/_gate_receipt.ps1 | 138 ++++++++++++++++++++++ scripts/worktree/install-gate.ps1 | 45 +++++++- tests/test_gate_install_receipt.py | 180 +++++++++++++++++++++++++++++ 3 files changed, 362 insertions(+), 1 deletion(-) create mode 100644 scripts/worktree/_gate_receipt.ps1 create mode 100644 tests/test_gate_install_receipt.py diff --git a/scripts/worktree/_gate_receipt.ps1 b/scripts/worktree/_gate_receipt.ps1 new file mode 100644 index 000000000..29df0fd4b --- /dev/null +++ b/scripts/worktree/_gate_receipt.ps1 @@ -0,0 +1,138 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +# +# Install receipts for the machine-global worktree gate (BACKLOG #1247). +# +# WHY THIS IS A SEPARATE FILE AND NOT INLINE IN install-gate.ps1. Everything here has to be testable, +# and install-gate.ps1 cannot be dot-sourced to reach its functions -- it runs its install body on +# load, and that body writes to ~/.claude, a MACHINE-GLOBAL location shared by every session on the +# box. A test that had to run the installer to exercise the receipt would be a test that installs the +# gate, which is the owner's action by design and not a thing a suite may do. This file defines +# functions and nothing else, so a test dot-sources it against a temp directory and never touches the +# real gate. +# +# WHAT WENT WRONG, and it is the reason the design is shaped this way. The installed gate's CONTENT +# changed on this box while three sessions ran against it, and afterwards NOBODY COULD SAY WHO WROTE +# IT. The change happened to be benign -- it moved the gate forward -- but an unattributable write to +# a shared safety control is the same class of event whichever direction it goes. +# +# THE MTIME IS THE TRAP, NOT THE GAP. `Copy-Item` carries the SOURCE file's LastWriteTime, so the +# installed copy inherits a timestamp from whichever checkout installed it. That is worse than having +# no timestamp: a correct stale-gate report was RETRACTED on the strength of one ("nothing wrote it +# today") and the retraction reached three sessions and the owner before a baseline hash reproved the +# original finding. An absent record makes a reader say "unknown"; a WRONG record makes them say +# something false with confidence. So nothing here repairs or writes mtime -- a corrected timestamp is +# still one mutable field asserting a fact nothing corroborates. +# +# The receipt is a record of the past, written at the moment of the write. That is the property that +# matters: a re-measurement can only ever see the present, so it can never distinguish "my instrument +# was wrong" from "the artifact changed". Only a record taken beforehand can. + +# DELIBERATELY NO `Set-StrictMode` HERE. Dot-sourcing runs a file in the CALLER'S scope, so a strict +# mode set in this file would silently impose itself on the rest of install-gate.ps1 -- a script +# written without it, where an unset variable is ordinary. The failure would appear as the installer +# throwing on a line this change never touched, and the cause would not be visibly connected to it. +# A helper that is dot-sourced must not configure its host. + +#: Beside the gate, not inside it -- the gate must stay byte-identical to its source or +#: tests/test_gate_installed_parity.py reds, and an embedded receipt would change its content. +function Get-GateReceiptPath([string]$GatePath) { + Join-Path (Split-Path -Parent $GatePath) "worktree_gate.install-receipt.json" +} + +#: Reads a receipt, or $null when there is none or it is unreadable. A corrupt receipt is treated as +#: ABSENT rather than as a failure: the caller's safe response to both is the same (refuse to claim +#: provenance), and throwing here would make an unreadable receipt harder to recover from than none. +function Read-GateReceipt([string]$GatePath) { + $p = Get-GateReceiptPath $GatePath + if (-not (Test-Path -LiteralPath $p)) { return $null } + try { Get-Content -LiteralPath $p -Raw | ConvertFrom-Json } catch { $null } +} + +#: The provenance verdict for an installed gate, as one of three words. The three-way split is the +#: whole point and collapsing it to a boolean loses the distinction the item exists for: +#: +#: ABSENT no gate installed. Nothing to protect; install freely. +#: UNRECORDED a gate is installed but carries no receipt. This is every gate installed before this +#: change, so it is the NORMAL first-run state and must NOT be fatal -- refusing here +#: would block the very re-install that adopts the mechanism. +#: VERIFIED installed content matches its receipt. Provenance is known. +#: MODIFIED installed content does NOT match its receipt. SOMETHING WROTE THIS FILE OUTSIDE THIS +#: INSTALLER. That is the defect this whole item is about, and it is the only verdict +#: that should stop an install and ask a human. +function Get-GateProvenance([string]$GatePath, [scriptblock]$HashFn) { + if (-not (Test-Path -LiteralPath $GatePath)) { return "ABSENT" } + $receipt = Read-GateReceipt $GatePath + if ($null -eq $receipt) { return "UNRECORDED" } + $installed = & $HashFn $GatePath + if ($receipt.installed_content_sha256 -eq $installed) { return "VERIFIED" } else { return "MODIFIED" } +} + +#: Preserve the bytes about to be overwritten, so a bad install is reversible. Byte-exact on purpose: +#: this is a recovery artifact, and folding line endings here would make it impossible to restore the +#: file that was actually there. +function Backup-GateBeforeWrite([string]$GatePath) { + if (-not (Test-Path -LiteralPath $GatePath)) { return $null } + $bak = "$GatePath.bak" + Copy-Item -LiteralPath $GatePath -Destination $bak -Force + $bak +} + +#: Records who wrote the gate, from where, what was written, and WHAT WAS REPLACED -- the last field +#: being the one that makes an unexpected change detectable rather than merely visible. +#: +#: The timestamp is taken HERE, at write time, in UTC, and is never derived from a file. See the +#: header: an inherited mtime is the failure this replaces. +function Write-GateReceipt { + param( + [Parameter(Mandatory)][string]$GatePath, + [Parameter(Mandatory)][string]$SourcePath, + [Parameter(Mandatory)][string]$RepoRoot, + [Parameter(Mandatory)][scriptblock]$HashFn, + [string]$ReplacedSha, + [string]$ReplacedProvenance, + [string]$BackupPath + ) + # EVERY GIT LOOKUP IS A STATEMENT, NEVER AN EXPRESSION. `try` is not an expression in PowerShell: + # written as `key = (try { ... } catch { ... })` the parser reads `try` as a COMMAND NAME, the file + # PARSES CLEAN, and at run time it fails with "The term 'try' is not recognized" -- which discards + # the WHOLE hashtable, writes a receipt containing the literal `null`, and still returns a path and + # exits 0. Measured here before this comment existed. That is the exact failure this file is meant + # to prevent, reproduced inside it: a record that exists, looks like a record, and says nothing. + # + # The git values are optional by design -- a receipt that throws when git is unavailable is a + # receipt nobody gets -- but optional must mean "recorded as null on purpose", not "silently lost". + $srcBlob = $null + try { $srcBlob = & git -C $RepoRoot hash-object $SourcePath 2>$null | Select-Object -First 1 } catch { $srcBlob = $null } + $wt = $null + try { $wt = & git -C $RepoRoot rev-parse --show-toplevel 2>$null } catch { $wt = $null } + $branch = $null + try { $branch = & git -C $RepoRoot rev-parse --abbrev-ref HEAD 2>$null } catch { $branch = $null } + + $receipt = [ordered]@{ + schema = "mefor.worktree-gate.install-receipt/1" + written_at_utc = [DateTime]::UtcNow.ToString("yyyy-MM-ddTHH:mm:ss.fffZ") + installed_by_repo = $RepoRoot + installed_by_worktree = $wt + installed_by_branch = $branch + source_path = $SourcePath + source_blob_sha = $srcBlob + installed_content_sha256 = (& $HashFn $GatePath) + replaced_content_sha256 = $ReplacedSha + replaced_provenance = $ReplacedProvenance + backup_path = $BackupPath + } + $path = Get-GateReceiptPath $GatePath + $json = $receipt | ConvertTo-Json -Depth 10 + # Round-trip AND confirm the result carries the one field that cannot be absent. A bare + # ConvertFrom-Json is not a control here: `null` is valid JSON, so the broken version above passed + # this guard every time. A check that its own failure mode satisfies is not a check. + $probe = $json | ConvertFrom-Json + if ($null -eq $probe -or -not $probe.written_at_utc) { + throw "refusing to write a receipt that carries no timestamp -- receipt construction failed" + } + $tmp = "$path.tmp-$PID" + Set-Content -LiteralPath $tmp -Value $json -Encoding utf8 + Move-Item -LiteralPath $tmp -Destination $path -Force + $path +} diff --git a/scripts/worktree/install-gate.ps1 b/scripts/worktree/install-gate.ps1 index 0964cb6ff..a9e737f47 100644 --- a/scripts/worktree/install-gate.ps1 +++ b/scripts/worktree/install-gate.ps1 @@ -50,6 +50,11 @@ param( [string[]]$Repo, [switch]$Uninstall, [switch]$Status, + # Proceed even when the installed gate's content does not match its own install receipt (BACKLOG + # #1247). A mismatch means something wrote this machine-global file outside this installer, so the + # default is to STOP and ask rather than overwrite the evidence. Required only for that one case: + # a gate with no receipt at all is the normal pre-#1247 state and installs without this. + [switch]$OverwriteUnverifiedGate, # Do not gate Task/Agent/Workflow dispatch from the primary (writes are still gated). [switch]$NoDispatchGate, # Gate the EnterWorktree tool (rule 4), which relocates a LIVE session into a worktree. @@ -81,6 +86,10 @@ $RepoRoot = (Resolve-Path (Join-Path $PSScriptRoot "..\..")).Path $HomeDir = if ($env:USERPROFILE) { $env:USERPROFILE } else { [Environment]::GetFolderPath('UserProfile') } $HooksDir = Join-Path $HomeDir ".claude/hooks" $GateDst = Join-Path $HooksDir "worktree_gate.ps1" + +# Install-receipt helpers (BACKLOG #1247). A separate file because it must be dot-sourceable by a +# test; this script cannot be, since loading it performs a machine-global install. +. (Join-Path $PSScriptRoot "_gate_receipt.ps1") $ReposFile = Join-Path $HooksDir "worktree-gate.repos.txt" # Marker so we can find (and remove) exactly the entries we added, without disturbing other hooks. @@ -438,7 +447,41 @@ $resolved = foreach ($r in $Repo) { } New-Item -ItemType Directory -Force -Path $HooksDir | Out-Null -Copy-Item -LiteralPath (Join-Path $RepoRoot "scripts\hooks\worktree_gate.ps1") -Destination $GateDst -Force + +# BACKLOG #1247 -- this write used to be a bare Copy-Item over a MACHINE-GLOBAL safety control, with +# no backup, no receipt and no log line. When the installed gate's content changed on this box while +# three sessions ran against it, nothing could say who wrote it. The four steps below exist so that +# question is answerable next time, and so an unexpected change STOPS the install instead of being +# silently overwritten -- an overwrite destroys the only evidence that anything happened. +$srcGateFile = Join-Path $RepoRoot "scripts\hooks\worktree_gate.ps1" +$provenance = Get-GateProvenance $GateDst ${function:Get-GateHash} +$replacedSha = if (Test-Path -LiteralPath $GateDst) { Get-GateHash $GateDst } else { $null } + +if ($provenance -eq "MODIFIED" -and -not $OverwriteUnverifiedGate) { + $r = Read-GateReceipt $GateDst + throw @" +REFUSING TO OVERWRITE: the installed gate does not match its own install receipt. + + gate : $GateDst + installed now : $replacedSha + receipt records : $($r.installed_content_sha256) + receipt written : $($r.written_at_utc) by $($r.installed_by_repo) + +Something wrote this file outside this installer. Overwriting would destroy the only evidence of +what it was. Inspect it first; then re-run with -OverwriteUnverifiedGate to proceed deliberately. + +DO NOT trust the file's timestamp to decide -- Copy-Item carries the SOURCE's LastWriteTime, so the +installed gate's mtime reflects whichever checkout installed it and not when it was written here. +"@ +} +if ($provenance -eq "UNRECORDED") { + Write-Warning "installed gate has no install receipt (installed before BACKLOG #1247, or written by something else). Recording its hash as replaced: $replacedSha" +} + +$backup = Backup-GateBeforeWrite $GateDst +Copy-Item -LiteralPath $srcGateFile -Destination $GateDst -Force +$receiptPath = Write-GateReceipt -GatePath $GateDst -SourcePath $srcGateFile -RepoRoot $RepoRoot ` + -HashFn ${function:Get-GateHash} -ReplacedSha $replacedSha -ReplacedProvenance $provenance -BackupPath $backup @( "# Primary checkouts governed by the worktree gate (scripts\hooks\worktree_gate.ps1)." diff --git a/tests/test_gate_install_receipt.py b/tests/test_gate_install_receipt.py new file mode 100644 index 000000000..ad0861031 --- /dev/null +++ b/tests/test_gate_install_receipt.py @@ -0,0 +1,180 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +"""Installing the machine-global worktree gate must leave a record of who wrote it (BACKLOG #1247). + +This exists because it went wrong and could not be diagnosed. The installed gate's content changed on +this box while three sessions ran against it, and afterwards nobody could say who wrote it. The change +was benign, which is not the point: an unattributable write to a shared safety control is the same +class of event whichever direction it moves the file. + +WHAT THESE TESTS DELIBERATELY DO NOT DO IS RUN THE INSTALLER. `install-gate.ps1` writes into +``~/.claude``, a machine-global location shared by every session on this box, and installing it is the +owner's action by design. A suite that had to install the gate to test the receipt would be a suite +that installs the gate. So the behaviour lives in ``scripts/worktree/_gate_receipt.ps1``, which +defines functions and nothing else and can be dot-sourced against a temp directory -- and the WIRING, +which cannot be tested that way, is pinned statically below. + +THE SPLIT IS THE DESIGN, and it is worth naming because each half is blind to the other's failure: +the behavioural tests would still pass if the installer never called any of these functions, and the +static test would still pass if every function were wrong. Neither is sufficient; both are cheap. +""" + +from __future__ import annotations + +import json +import shutil +import subprocess +from pathlib import Path + +import pytest + +ROOT = Path(__file__).resolve().parents[1] +HELPER = ROOT / "scripts" / "worktree" / "_gate_receipt.ps1" +INSTALLER = ROOT / "scripts" / "worktree" / "install-gate.ps1" + +pytestmark = pytest.mark.skipif(shutil.which("pwsh") is None, reason="pwsh not on PATH") + + +def run_ps(body: str) -> str: + """Dot-source the receipt helper and run `body`. Never touches the real gate.""" + script = f". '{HELPER.as_posix()}'\n{body}" + r = subprocess.run( + ["pwsh", "-NoProfile", "-NonInteractive", "-Command", script], + capture_output=True, + text=True, + check=False, + ) + assert r.returncode == 0, f"pwsh failed: {r.returncode}\nSTDOUT:{r.stdout}\nSTDERR:{r.stderr}" + return r.stdout.strip() + + +# A deliberately trivial injected hash. The REAL hash (Get-GateHash) folds CRLF and is covered by +# tests/test_gate_installed_parity.py; re-testing it here would test that file twice and this one not +# at all. What is under test is the receipt state machine, so the hash only has to be a function of +# content. That the installer passes the real one is pinned by the static test at the bottom. +HASH_FN = "{ param($p) (Get-FileHash -LiteralPath $p -Algorithm SHA256).Hash }" + + +@pytest.fixture +def gate(tmp_path: Path) -> Path: + p = tmp_path / "worktree_gate.ps1" + p.write_text("# pretend gate v1\n", encoding="utf-8") + return p + + +def test_absent_when_no_gate_is_installed(tmp_path: Path) -> None: + missing = tmp_path / "worktree_gate.ps1" + out = run_ps(f"Get-GateProvenance '{missing.as_posix()}' {HASH_FN}") + assert out == "ABSENT" + + +def test_unrecorded_when_a_gate_exists_with_no_receipt(gate: Path) -> None: + """The normal state of every gate installed before this change -- and it must NOT be fatal. + + Refusing here would block the very re-install that adopts the mechanism, which would make the fix + for an unattributable write into a reason nobody can install the gate at all. + """ + out = run_ps(f"Get-GateProvenance '{gate.as_posix()}' {HASH_FN}") + assert out == "UNRECORDED" + + +def test_verified_after_a_receipt_is_written(gate: Path) -> None: + out = run_ps( + f"$null = Write-GateReceipt -GatePath '{gate.as_posix()}' -SourcePath '{gate.as_posix()}' " + f"-RepoRoot '{ROOT.as_posix()}' -HashFn {HASH_FN}\n" + f"Get-GateProvenance '{gate.as_posix()}' {HASH_FN}" + ) + assert out == "VERIFIED" + + +def test_modified_when_something_writes_the_gate_behind_the_receipt(gate: Path) -> None: + """The defect this item exists for: a write nobody can attribute. + + This is the assertion that has to be able to fail. If Get-GateProvenance stopped comparing, every + other test here would still pass -- ABSENT, UNRECORDED and VERIFIED are all reachable without a + working comparison. + """ + out = run_ps( + f"$null = Write-GateReceipt -GatePath '{gate.as_posix()}' -SourcePath '{gate.as_posix()}' " + f"-RepoRoot '{ROOT.as_posix()}' -HashFn {HASH_FN}\n" + f"Set-Content -LiteralPath '{gate.as_posix()}' -Value '# someone else wrote this'\n" + f"Get-GateProvenance '{gate.as_posix()}' {HASH_FN}" + ) + assert out == "MODIFIED" + + +def test_the_receipt_timestamp_is_taken_at_write_time_not_inherited(gate: Path) -> None: + """The mtime is the trap, not the gap. + + Copy-Item carries the SOURCE's LastWriteTime, so an installed gate's mtime reflects whichever + checkout installed it. A correct stale-gate report was once RETRACTED on the strength of one, and + the retraction reached three sessions and the owner before a baseline hash reproved it. So the + receipt's timestamp must not be derived from any file -- here the gate is backdated years and the + receipt must disagree with it. + """ + out = run_ps( + f"$g = '{gate.as_posix()}'\n" + f"(Get-Item -LiteralPath $g).LastWriteTimeUtc = [DateTime]::new(2001,1,1)\n" + f"$p = Write-GateReceipt -GatePath $g -SourcePath $g -RepoRoot '{ROOT.as_posix()}' -HashFn {HASH_FN}\n" + f"Get-Content -LiteralPath $p -Raw" + ) + receipt = json.loads(out) + assert not receipt["written_at_utc"].startswith("2001"), ( + "the receipt inherited the file's mtime, which is exactly the defect it replaces" + ) + assert receipt["written_at_utc"].endswith("Z"), "timestamp must be explicit UTC" + + +def test_the_replaced_bytes_are_recoverable(gate: Path) -> None: + """A bad install must be reversible; the backup is byte-exact on purpose.""" + out = run_ps( + f"$b = Backup-GateBeforeWrite '{gate.as_posix()}'\n" + f"Set-Content -LiteralPath '{gate.as_posix()}' -Value '# overwritten'\n" + f"Get-Content -LiteralPath $b -Raw" + ) + assert "pretend gate v1" in out + + +def test_a_corrupt_receipt_reads_as_absent_rather_than_throwing(gate: Path) -> None: + """Both states have the same safe response -- do not claim provenance -- and throwing would make + an unreadable receipt harder to recover from than a missing one.""" + receipt = gate.parent / "worktree_gate.install-receipt.json" + receipt.write_text("{not json at all", encoding="utf-8") + out = run_ps(f"Get-GateProvenance '{gate.as_posix()}' {HASH_FN}") + assert out == "UNRECORDED" + + +# --------------------------------------------------------------------------- the wiring + + +def test_the_installer_actually_calls_the_receipt_machinery() -> None: + """The behavioural tests above are blind to an installer that never calls any of this. + + That is not hypothetical here: the sibling defect this file's neighbours exist for was a rule that + worked in isolation and was never wired, so it was dead code the moment it shipped. + """ + text = INSTALLER.read_text(encoding="utf-8") + for call in ("Get-GateProvenance", "Backup-GateBeforeWrite", "Write-GateReceipt"): + assert call in text, f"install-gate.ps1 never calls {call}" + assert "_gate_receipt.ps1" in text, "installer does not dot-source the receipt helper" + # The real hash, not a local one -- a second digest basis would let the receipt and + # tests/test_gate_installed_parity.py disagree about one file. + assert "${function:Get-GateHash}" in text, "installer must pass the real Get-GateHash" + + +def test_a_mismatched_gate_stops_the_install_by_default() -> None: + """An overwrite destroys the only evidence that anything happened, so it must not be the default.""" + text = INSTALLER.read_text(encoding="utf-8") + assert "OverwriteUnverifiedGate" in text, "no explicit flag exists to override a mismatch" + assert 'MODIFIED" -and -not $OverwriteUnverifiedGate' in text, ( + "the refusal is not gated on MODIFIED plus the absence of the override" + ) + + +def test_the_fix_does_not_repair_mtime() -> None: + """Explicitly rejected by the item: a corrected timestamp is still one mutable field asserting a + fact nothing corroborates. The record has to be the receipt, not a better-looking mtime.""" + text = INSTALLER.read_text(encoding="utf-8") + HELPER.read_text(encoding="utf-8") + assert "LastWriteTime =" not in text and "LastWriteTimeUtc =" not in text, ( + "something assigns a file timestamp; #1247 forbids fixing this by touching mtime" + ) From b3ecfc7be8438d432aaa330a9b1ae33141c219d9 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 18:59:52 -0500 Subject: [PATCH 03/16] feat(security): structural estate-identifier backstop for the leak gate (BACKLOG #321, Proposed 3) A required merge context exited 0 on content carrying a real site code. scan_forbidden.py:10-12 is explicit that gitleaks finds SECRETS, not this class, and the file WAS scanned -- the detectors simply did not match. Every existing site-code detector is PREFIX-DRIVEN, so with no token file loaded it degrades to the always-failing _NEVER sentinel: blind until the owner supplies data. This adds a STRUCTURAL detector that works with nothing loaded, which is what makes it a backstop rather than a second thing waiting on the owner. THE SHAPE HAD TO EARN ITS PRECISION, because a leak gate that cries wolf gets disabled and that is strictly worse than the hole it closes. Measured over the tracked tree (1,953 files): a bare delimited six-digit run matches 637 lines in 146 files. Requiring the run to JOIN a letter-bearing identifier segment across an underscore takes that to 5 -- every one of them this gate's own illustrations of the shape, now rewritten with the house placeholder. Post-fix: 0 new hits on content, 0 on paths, 0 on a full --path . walk including untracked files. Whole-tree scan cost 3.50s to 4.13s. IT CATCHES THE THING THAT GOT THROUGH. Replayed against the pre-removal revision the item cites, the detector fires on exactly one line of that file and on zero lines after the removal. WIDTH IS PINNED AT EXACTLY SIX WITH NO LEADING-ZERO CARVE-OUT. A 5-to-7 band only works with a no-leading-zero rule, and that is a silent under-detection hole in a gate whose filed defect IS a silent hole -- the numeric prefix accepts a leading zero, so it is reachable. A HAZARD ALL THREE CANDIDATE DESIGNS MISSED: each excluded a dot after the digit run, so a feed module FILENAME written in prose did not match -- and a filename was half the evidenced leak. Permitting the dot costs zero additional hits on either corpus. Both arms now cover it. THE SELF-SCAN CANARY NEEDED EIGHT DIGITS, NOT SIX. A probe literal in the scanner's own source must survive its own new detector AND a real prefix list no author can see. An eight-digit run has no six-digit window with a boundary on both sides, so it cannot be a site code under any prefix list. WHAT THIS DOES NOT CLOSE, and the module docstring now says so in the file itself: the item names TWO token classes and only the SITE-CODE half is closable by shape. A partner-product name is a proper noun in prose with no width, character class, separator or position regularity. That half closes only under Proposed 1, which is owner-run token data and is not mine. Shipping this as "the estate-identifier backstop" would let a green run read as "no estate identifiers present" -- the same defect the item diagnoses, recreated one level up. Tests assert TOKENS_PRESENT is False first: a prefix-free detector has no globals to monkeypatch, and that precondition is what makes the backstop claim non-vacuous. Includes a liveness guard that the detector is not the _NEVER sentinel, because no floor mechanism counts a structural detector. Verified independently of the build: scanner exits 0 over the tracked tree, detector fires on a synthetic positive and stays quiet on a git sha and a bare number; ruff check and format clean, mypy strict clean over 266 files, 106 passed on the directly-affected modules. NOT DONE, deliberately: docs/BACKLOG.md is untouched. The item's own proposed regex at :2703 matches NEITHER example the item itself gives, and correcting a ledger body is not a builder's. --- messagefoundry/config/wiring.py | 3 +- scripts/security/scan-allowlist.txt | 2 +- scripts/security/scan_forbidden.py | 106 ++++++++++-- tests/negative_controls.toml | 16 +- tests/test_scan_forbidden.py | 9 +- tests/test_scan_tokens_source.py | 242 +++++++++++++++++++++++++++- 6 files changed, 357 insertions(+), 21 deletions(-) diff --git a/messagefoundry/config/wiring.py b/messagefoundry/config/wiring.py index 0790fee4d..f62abad31 100644 --- a/messagefoundry/config/wiring.py +++ b/messagefoundry/config/wiring.py @@ -1881,7 +1881,8 @@ def PassThrough() -> ConnectionSpec: its transformed message into this inbound (naming it like an outbound), and the engine re-ingresses that body as a **new, independent inbound message** on this channel, routed by this inbound's own Router. This is the Corepoint ``PT_*`` pattern: one logical feed fans out across internal connectors - and re-routes deeper (e.g. ``PT_000000_ADT_2``) without an external hop. + and re-routes deeper (e.g. ``PT__ADT_2``, where ```` is the estate's site code) without + an external hop. It is an ordinary ``inbound(...)`` otherwise: declare its ``router`` (which re-routes the message) and ``content_type`` (``hl7v2`` → :class:`~messagefoundry.parsing.message.Message`; ``x12``/``text``/ diff --git a/scripts/security/scan-allowlist.txt b/scripts/security/scan-allowlist.txt index 213ce9f9f..f0afddb6e 100644 --- a/scripts/security/scan-allowlist.txt +++ b/scripts/security/scan-allowlist.txt @@ -8,7 +8,7 @@ # print " ms tasks". A task count that lands in the # site-code range (e.g. WRITELOG ... 993496 tasks) collides with the site-code guard (99\d{4}) despite # being a pure engine perf counter with no customer-data path. This row shape is unambiguous DMV output, -# so a real site code embedded in a path/HL7 field/prose (PT_990700_ADT, ^993496^) does NOT match it. +# so a real site code embedded in a path/HL7 field/prose (PT__ADT, ^^) does NOT match it. ^\s*[A-Z0-9_]+\s+\d+ ms\s+\d+ tasks\s*$ # OIDC Core spec-section citations in the federated-SSO claim ladder (ADR 0142) read as dotted diff --git a/scripts/security/scan_forbidden.py b/scripts/security/scan_forbidden.py index 9ee902189..cdc175462 100644 --- a/scripts/security/scan_forbidden.py +++ b/scripts/security/scan_forbidden.py @@ -11,17 +11,21 @@ *customer-identifying* strings -- a partner/vendor name, a real site-estate's site-code prefix, a routable host IP -- which are not credentials but must never reach the open-source repo. -Token authority is EXTERNALIZED. The committed source carries only STRUCTURAL detectors (a routable- -IPv4 detector and the generic site-code *shape*); the real customer/vendor name patterns, estate -substrings, and the site-code numeric prefix are loaded at runtime from, in order of precedence: +Token authority is EXTERNALIZED. The committed source carries only STRUCTURAL detectors -- at least a +routable-IPv4 detector, a worktree/branch slug detector, an absolute-home-path detector and the +prefix-free estate-identifier *shape*; the real customer/vendor name patterns, estate substrings, and +the site-code numeric prefix are loaded at runtime from, in order of precedence: 1. ``MEFOR_FORBIDDEN_TOKENS`` -- either a path to a token file OR the token content inline (newline-separated, same format). Used in CI via the Actions secret of the same name. 2. ``scripts/security/scan-tokens.local.txt`` -- a git-ignored local file (pre-commit). A synthetic template ships as ``scan-tokens.local.txt.example``. -With no source present the scanner degrades to STRUCTURAL-ONLY (routable-IPv4 only); the name / -estate / site-code detectors are simply empty -- appropriate for a fork with no access to the secret. +With no source present the scanner degrades to STRUCTURAL-ONLY (the shape detectors above stay live); +the name / estate / site-code detectors are simply empty -- appropriate for a fork with no access to +the secret. STRUCTURAL-ONLY IS NOT A CLASS-LEVEL CLEAN: the shape detectors catch a *shape*, so a +green structural-only run says nothing about a partner/vendor name, or about a site code carried in +prose, in a hyphenated name, or in an HL7 field. Only a loaded token source covers those. Set ``MEFOR_REQUIRE_TOKENS=1`` to fail closed (exit 2) instead when the source is absent, so a misconfigured owner/CI run refuses rather than silently under-scanning. @@ -188,6 +192,60 @@ r"[A-Za-z][A-Za-z0-9._-]*" ) +# Ported-estate identifier SHAPE. The site-code detectors below are keyed on a numeric PREFIX loaded +# from the token source, so they are _NEVER until the owner adds that estate's prefix -- and an estate +# whose prefix nobody has added yet is exactly the one that leaks. Measured on this repo's own history: +# a required merge context exited 0 on a tracked file carrying a real site code, because the file WAS +# scanned and the loaded detectors simply did not cover that prefix (BACKLOG #321). This one is keyed +# on STRUCTURE, so like the two detectors above it fires with no token source at all -- a backstop +# rather than a second thing waiting on the owner. +# +# The UNDERSCORE ANCHOR is the entire design, and it is what keeps a required gate from crying wolf. +# A bare delimited six-digit run matches 1,414 lines across 152 tracked files (HL7 samples, DMV soak +# rows, benchmark artifacts, lock files) -- counted over EVERY scanned file, which is the population +# this detector actually sees, since unlike the site-code detectors below it is not skip-gated. (The +# skip-gated population is 638/145; quoting that number for an ungated detector would be an +# instrument that answers the adjacent question.) Requiring the run to join a LETTER-BEARING +# identifier segment takes that to 5, every one of them this gate's own illustration of the shape, +# and to 0 once those five adopt the house placeholder. That is the +# form the class actually takes here -- the [TYPE]_[PARTNER]_[MESSAGE] connection convention +# (docs/CONNECTIONS.md) and the Corepoint PT_* pattern both produce it, and so did both identifiers +# the #321 audit found -- replayed against the content that got through, this fires on it and on no +# other line of that file. +# +# WIDTH IS PINNED AT SIX because that is what the format yields -- a site code is a numeric prefix +# plus four digits (see _SITE_CODE_FILE below) over the two-digit prefix space the anonymizer models +# (anon/surrogates.py builds non-site prefixes from range(10, 100)). Measured either side: five digits +# collides with the harness's zero-padded connection names (IB_CS_00000 and siblings, three files), +# seven matches nothing at all. A leading-zero carve-out would buy the width-5 band back, and is +# deliberately NOT taken: it is a silent under-detection hole in a gate whose filed defect is an +# unnoticed blind spot, and the one line it would have rescued is a docstring example that the house +# placeholder convention fixes instead. +# +# HYPHEN IS EXCLUDED, measured: the same shape joined by "-" re-admits 11 hits across 6 files, every +# one a false positive (a dated OASIS namespace quoted in security-critical code, a CFR citation, a +# sandbox depth constant, a synthetic MRN). +# +# NOT gated on the _SITE_SKIP_* sets, unlike the site-code detectors. Their skip exists because BARE +# digit runs storm in lock/SVG/password files; the anchor already removes that storm (measured: zero +# matches across those files), so the skip would only open a hole -- a flame-graph SVG's frame labels +# are function names, and a transform function name is one of the two forms this exists for. +_ESTATE_ID_SHAPE = re.compile( + r"(?_ADT`, `IB_FEED_.py`. The trailing lookahead permits `.` + # so a module filename written in prose is not waved through, but still pins the run at exactly + # six digits. + r"(?:[A-Za-z][A-Za-z0-9]*_\d{6}(?![A-Za-z0-9])" + # Arm 2, code-leading: `_router.py`. It also rescues a segment arm 1 cannot reach, because + # the segment before the code starts with a digit (`IB_2ND__MFN`). No trailing lookahead: + # the following segment must merely CONTAIN a letter, which is what rejects `1_000000_2`. + r"|\d{6}_[A-Za-z0-9]*[A-Za-z])" +) +#: Shared so the content hit and the file-name hit are one grep, and so the reason describes the SHAPE +#: rather than asserting the class: this cannot tell a site code from a coincidental six-digit segment, +#: and a reason reading "site code" would make a green run read as "no site codes here". +_ESTATE_ID_REASON = "six-digit run inside an underscore-joined identifier" + # A pattern that can never match -- the "detector off" sentinel used for the site-code regexes when no # numeric prefix is loaded (structural-only / fork context). ``(?!)`` is an always-failing assertion, # so ``.search``/``.finditer``/``.fullmatch`` never fire and ``.pattern`` stays a valid string. @@ -334,9 +392,12 @@ def forbidden_path_reason(posix: str) -> str | None: ESTATE_TOKENS: tuple[str, ...] = () SITE_CODE_RE: re.Pattern[str] = _NEVER #: Boundary-aware site-code FILE detector: fires on a code delimited by non-alphanumerics -#: (``PT_990123_ADT`` -> matches) but NOT on the prefix embedded in a longer alphanumeric run +#: (``PT__ADT`` -> matches) but NOT on the prefix embedded in a longer alphanumeric run #: (a SHA, a DOB, a dotted version), so the broad-substring false-positive storm does not happen on -#: source files. ``.`` is a boundary exclusion too (a real site code is never dot-adjacent). +#: source files. ``.`` is a boundary exclusion too (a real site code is never dot-adjacent). The +#: example above uses the house ```` placeholder rather than a digit run, because a concrete one +#: written here trips ``_ESTATE_ID_SHAPE``; the digit-level contrast is demonstrated instead by +#: ``tests/test_scan_forbidden.py::test_scan_file_site_code_ignores_embedded_digit_runs``. _SITE_CODE_FILE: re.Pattern[str] = _NEVER #: The site-code detectors above match a prefix followed by four LITERAL digits. But the SECRET IS THE #: PREFIX, not any particular code, so a doc or comment that writes the PATTERN itself -- the prefix @@ -766,12 +827,19 @@ def token_floor_failure(min_detectors: int | dict[str, int] | None = None) -> st #: Benign strings an allowlist entry must NOT match. An entry that matches any of these is broad #: enough to veto ordinary source lines, and therefore broad enough to switch the gate off wholesale. #: The empty string is included so a pattern that can match nothing-in-particular is caught too. +#: The last entry is the canary for ``_ESTATE_ID_SHAPE``. ``0123456789`` rejects a bare ``\d{6}``, but +#: it carries no underscore, so it ACCEPTED ``_\d{6}`` / ``\d{6}_`` -- an entry that narrow-looking +#: would veto every line joining a digit run to an identifier segment, switching the whole gate off on +#: those lines while the loaded-counts diagnostic still read healthy. This canary is a dated release +#: tag: an eight-digit run, so no six-digit window has a boundary on both sides and it can therefore +#: never be a site code under ANY prefix list -- it tests allowlist BREADTH without becoming a hit. _ALLOWLIST_CANARIES: tuple[str, ...] = ( "", "the quick brown fox jumps over the lazy dog", "def handler(message: Message) -> list[Send]:", "# a perfectly ordinary comment", "0123456789", + "v_20260814_rc", ) @@ -909,12 +977,26 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = # inside it. Scanning stops here; content hits on a file that must not exist add nothing. if reason := forbidden_path_reason(posix): return [f"{path}:0: {reason}"] + hits: list[str] = [] + # The NAME is half of what #321 found: one of the two leaked identifiers was a feed module's + # filename, and a module need not repeat its own name in its text. Placed before the binary + # early-return for the same reason the location rule above is -- a DICOM or PDF sample named with + # a site code is exactly as much of a leak as the .py beside it, and _read_text drops binaries + # unread. Line 0 because the finding is the file, not a location inside it. Unlike a location-rule + # hit this does NOT stop the scan: the content still has to be judged. + # + # This one hit necessarily carries the offending string, because the string is the path and every + # hit names its path. That is not a new disclosure -- by the time CI scans it the file is already + # in the public tree and in the PR's file list, and at pre-commit time nothing is public yet -- but + # it is why the remedy is renaming the file, not an ALLOWLIST line: the allowlist is a per-line + # content veto and cannot reach this, exactly as it cannot reach the location rule. + if _ESTATE_ID_SHAPE.search(posix): + hits.append(f"{posix}:0: {_ESTATE_ID_REASON}, in the file NAME") text = _read_text(path) if text is None: - return [] + return hits ip_scan = path.suffix not in _IP_SKIP_SUFFIXES and path.name not in _IP_SKIP_NAMES site_scan = path.suffix not in _SITE_SKIP_SUFFIXES and path.name not in _SITE_SKIP_NAMES - hits: list[str] = [] for lineno, line in enumerate(text.splitlines(), 1): if any(a.search(line) for a in ALLOWLIST): continue @@ -955,6 +1037,12 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = hits.append( f"{posix}:{lineno}: security-record content (requirement id beside a verdict)" ) + # Reason-only for the same reason as the two above, and NOT ``ctx``-appended even under + # show_context: the identifier IS the disclosure. + if _ESTATE_ID_SHAPE.search(line): + hits.append( + f"{posix}:{lineno}: {_ESTATE_ID_REASON} (the ported-estate site-code shape)" + ) # Estate substrings run LAST and only on a line nothing else flagged: the sets overlap (the # customer name is typically in [names] AND [estate]), and double-reporting one line adds noise # rather than information. What this adds is the case no other detector can reach -- a token diff --git a/tests/negative_controls.toml b/tests/negative_controls.toml index 902fb9306..2903859b9 100644 --- a/tests/negative_controls.toml +++ b/tests/negative_controls.toml @@ -300,23 +300,31 @@ observed = "Each planted shape is reported and the real tree is clean, in this s context = "forbidden-content (customer/PHI leak guard)" plants = """ A customer name, a case-sensitive site code, a routable host IP, and a file under docs/security/ caught -by its PATH alone; plus a run that examines zero files, which must refuse rather than report clean. +by its PATH alone; plus a run that examines zero files, which must refuse rather than report clean. And +the #321 class specifically: an estate-shaped identifier caught with NO token source loaded, which is +the only state in which the prefix-keyed site-code detectors are off. """ red = [ "tests/test_scan_forbidden.py::test_scan_file_flags_customer_name", "tests/test_scan_forbidden.py::test_scan_file_flags_site_code", "tests/test_scan_forbidden.py::test_a_file_under_docs_security_is_flagged_by_its_path_alone", "tests/test_scan_forbidden.py::test_zero_examined_still_refuses_rather_than_reporting_clean", + "tests/test_scan_tokens_source.py::test_estate_identifier_shape_is_flagged_without_any_token_source", + "tests/test_scan_tokens_source.py::test_an_estate_shaped_file_NAME_is_flagged_by_the_path_alone", ] holds = """ -Private and documentation IP ranges, ordinary docs paths, and clean text must all pass. This is the -asymmetry with the most history behind it: BACKLOG #321 and #325 are both this gate failing to fire, -and a control that reddened on 10.0.0.1 or on docs/CI.md would have been relaxed rather than trusted. +Private and documentation IP ranges, ordinary docs paths, ordinary digit runs, and clean text must all +pass. This is the asymmetry with the most history behind it: BACKLOG #321 and #325 are both this gate +failing to fire, and a control that reddened on 10.0.0.1 or on docs/CI.md would have been relaxed +rather than trusted. The estate-shape backstop is the sharpest case -- it is prefix-free by design, so +nothing but its own negative controls stands between it and matching every six-digit run in the tree. """ green = [ "tests/test_scan_forbidden.py::test_scan_file_allows_private_and_doc_ips", "tests/test_scan_forbidden.py::test_the_path_detector_does_not_flag_ordinary_paths", "tests/test_scan_forbidden.py::test_scan_file_clean_text_has_no_hits", + "tests/test_scan_tokens_source.py::test_ordinary_digit_runs_do_not_trip_the_estate_identifier_shape", + "tests/test_scan_tokens_source.py::test_ordinary_paths_do_not_trip_the_estate_identifier_shape", ] observed = """ Every planted shape is flagged and every benign one passes, in this suite. The gate additionally fails diff --git a/tests/test_scan_forbidden.py b/tests/test_scan_forbidden.py index e7b166da3..96e442b18 100644 --- a/tests/test_scan_forbidden.py +++ b/tests/test_scan_forbidden.py @@ -50,6 +50,11 @@ def _load_scanner(): # detector and the in-memory SITE_CODE_RE so no real site code appears in this now-scanned file. _SYNTH_SITE_CODE_RE = re.compile(r"99\d{4}") _SYNTH_SITE_CODE_FILE = re.compile(r"(?_ADT`` is a +#: live match for the scanner's own prefix-free ``_ESTATE_ID_SHAPE`` detector, and this file is scanned +#: by the gate it tests -- so a literal here would make the suite trip its own detector. Same defusal +#: as ``_routable_ip`` below. +_SYNTH_CODE = "99" + "0210" @pytest.fixture @@ -128,9 +133,9 @@ def test_scan_file_flags_site_code(sf, tmp_path: Path) -> None: # connection name reach the mirror. The ``_``-delimited code is caught even though a bare ``\b`` # boundary would miss it. p = tmp_path / "wiring.py" - p.write_text("re-routes deeper (e.g. ``PT_990210_ADT_2``)\n", encoding="utf-8") + p.write_text(f"re-routes deeper (e.g. ``PT_{_SYNTH_CODE}_ADT_2``)\n", encoding="utf-8") hits = sf.scan_file(p, show_context=True) # reason-only by default; see the IP test above - assert any("site code (990210)" in h for h in hits) + assert any(f"site code ({_SYNTH_CODE})" in h for h in hits) def test_scan_file_site_code_ignores_embedded_digit_runs(sf, tmp_path: Path) -> None: diff --git a/tests/test_scan_tokens_source.py b/tests/test_scan_tokens_source.py index 237cdbfc7..e737ff22e 100644 --- a/tests/test_scan_tokens_source.py +++ b/tests/test_scan_tokens_source.py @@ -41,6 +41,11 @@ #: collision the convention exists to avoid. _STANDIN = "SITEA" +#: A synthetic site code (the shipped example's non-real ``99`` prefix plus four digits), assembled +#: from parts for the same reason the routable IP below is: a whole literal in an identifier-shaped +#: probe is itself a match for the prefix-free _ESTATE_ID_SHAPE detector, and this file is scanned. +_SYNTH_CODE = "99" + "0123" + # A routable probe IP, built from parts so no literal dotted-quad appears in this tracked file -- # including in this comment, which is scanned like any other line. _ROUTABLE_IP = ".".join(["8", "8", "8", "8"]) @@ -109,11 +114,16 @@ def test_structural_only_scan_file_flags_routable_ip( assert any(_ROUTABLE_IP in h for h in ctx) -def test_committed_files_contain_no_routable_ip( +def test_committed_files_carry_no_structural_forbidden_content( monkeypatch: pytest.MonkeyPatch, ) -> None: - # Scan the committed scanner + its .example with the structural detector: any routable IP baked - # into them would surface here. (Their only IPs are RFC5737/RFC1918 allow-listed prefixes.) + # Scan the committed scanner + its .example with EVERY structural detector -- the assertion is an + # empty hit list, not an IP-specific one, and the previous name (...contain_no_routable_ip) named + # one detector for a check that covers all of them. That mismatch matters in the direction it + # fails: this is what catches the gate self-tripping on its own illustration of a shape, and a + # reader scanning for such a guard would not have recognised it under the old name. + # (The committed IPs are RFC5737/RFC1918 allow-listed prefixes; the site-code and estate-shape + # examples both use the house ```` placeholder.) mod = _load(None, monkeypatch) for path in (_SCANNER, _EXAMPLE): assert mod.scan_file(path) == [], f"{path.name} carries structural forbidden content" # type: ignore[attr-defined] @@ -140,7 +150,9 @@ def test_example_tokens_match_as_specified(monkeypatch: pytest.MonkeyPatch) -> N # Estate substring inside a field-like body. assert any("estate token" in r for r in mod.scan_text("PID|exampleco|x", include_estate=True)) # type: ignore[attr-defined] # Boundary-aware site-code file detector. - assert mod._SITE_CODE_FILE.search("PT_990123_ADT") is not None # type: ignore[attr-defined] + # Assembled, not written whole: ``PT__ADT`` is a live match for the scanner's own + # prefix-free _ESTATE_ID_SHAPE detector, and this file is scanned by the gate it tests. + assert mod._SITE_CODE_FILE.search(f"PT_{_SYNTH_CODE}_ADT") is not None # type: ignore[attr-defined] assert mod._SITE_CODE_FILE.search("ab990123cd") is None # type: ignore[attr-defined] @@ -1144,3 +1156,225 @@ def test_estate_only_token_still_caught_by_the_file_scan( hits = mod.scan_file(f, "tests/lanes.py") # type: ignore[attr-defined] assert any("estate token" in h for h in hits) assert not any("zorpnet" in h.lower() for h in hits), "reason-only" + + +# -------------------------------------------------------------------------------------------------- +# Prefix-free estate-identifier SHAPE backstop (BACKLOG #321). The site-code detectors are keyed on a +# numeric prefix loaded from the private token source, so they are OFF for any estate whose prefix +# nobody has added -- and that is the estate that leaks. This one is keyed on structure, so it is live +# with no token source at all, which is what these tests establish: every one asserts TOKENS_PRESENT +# is False first, so a pass can never be borrowed from a loaded prefix. +# +# Fixtures are ASSEMBLED, never written whole: this file is scanned by the gate it tests, so a literal +# probe would make the suite trip its own detector. +# -------------------------------------------------------------------------------------------------- + +_SHAPE_REASON = "six-digit run inside an underscore-joined identifier" + + +def _shape_hits(mod: ModuleType, tmp_path: Path, content: str, rel: str) -> list[str]: + """``scan_file`` hits for one line of content, at an explicit repo-relative path. + + The path is always given: the default is the ABSOLUTE tmp path, which would put the machine's + directory layout into the very argument the path arm judges. + """ + f = tmp_path / "probe.txt" + f.write_text(content, encoding="utf-8") + hits: list[str] = mod.scan_file(f, rel) # type: ignore[attr-defined] + return hits + + +def test_estate_identifier_shape_is_flagged_without_any_token_source( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """The #321 defect, stated as a test: a required merge context exited 0 on a tracked file carrying + a real site code, because the prefix that would have caught it was not in the loaded list. + + Both identifier forms the audit recorded are covered -- a ported feed module name and a transform + function name. + """ + mod = _load(None, monkeypatch) + assert mod.TOKENS_PRESENT is False, "precondition: structural-only" # type: ignore[attr-defined] + assert mod._SITE_CODE_FILE.search(_SYNTH_CODE) is None, ( # type: ignore[attr-defined] + "precondition: the PREFIX-keyed detector is off, so only the shape can be doing the work" + ) + for content in ( + f"see IB_FILE_HR_Materials_{_SYNTH_CODE}_MFN.py for the mapping\n", + f"def xform_{_SYNTH_CODE}_to_erp_mfn(msg):\n", + ): + hits = _shape_hits(mod, tmp_path, content, "docs/notes.md") + assert any(_SHAPE_REASON in h for h in hits), content + # Reason-only: the identifier IS the disclosure, and this gate fails into a world-readable + # Actions log on the public repo. + assert not any(_SYNTH_CODE in h for h in hits), content + + +def test_estate_identifier_shape_catches_the_leading_and_embedded_forms( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """Both regex arms must be reachable. The code-leading arm is not decoration: it is the only one + that can see a code whose preceding identifier segment starts with a DIGIT.""" + mod = _load(None, monkeypatch) + assert mod.TOKENS_PRESENT is False, "precondition: structural-only" # type: ignore[attr-defined] + for content in ( + f"module {_SYNTH_CODE}_mfn_router.py\n", # code-leading, dotted suffix + f"conn = 'IB_2ND_{_SYNTH_CODE}_MFN'\n", # digit-led neighbour, reachable only by that arm + f"a feed named IB_FEED_{_SYNTH_CODE}.py in prose\n", # code-trailing before a dot + ): + hits = _shape_hits(mod, tmp_path, content, "docs/notes.md") + assert any(_SHAPE_REASON in h for h in hits), content + + +def test_ordinary_digit_runs_do_not_trip_the_estate_identifier_shape( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """NEGATIVE CONTROL, and the one that decides whether this detector survives contact with a + required merge context. + + Without it, a rule that flagged every digit run would pass every assertion above and look + identical to a working one -- and it would be worse than the hole it closes, because a gate that + cries wolf gets bypassed. Every class below was measured on the tracked tree: a BARE delimited + six-digit run alone matches 1,414 lines across 152 files, and the underscore anchor is what + removes all of them. + """ + mod = _load(None, monkeypatch) + assert mod.TOKENS_PRESENT is False, "precondition: structural-only" # type: ignore[attr-defined] + for content, expected in ( + (f"standalone {_SYNTH_CODE} here\n", False), # bare delimited run: the 637-line class + (f"hash aff07c{_SYNTH_CODE}ff\n", False), # embedded in a hex digest + (f"dob 20{_SYNTH_CODE}\n", False), # digit-prefixed + (f"ratio 75.{_SYNTH_CODE}\n", False), # decimal fraction + (f"ver 1.{_SYNTH_CODE}.2\n", False), # dotted version + ("ADR_0093 and BACKLOG_1234 and HANDBACK_2026\n", False), # width 4: the repo's real mass + ("error_2812 = module_1230\n", False), # width 4 again, arbitrary test ids + ("IB_CS_00000 OB_00007_02\n", False), # width 5, harness zero-padded names + ("x_1234567 and 1234567_x\n", False), # width 7 + ("chunk_size = 1_000_000\n", False), # Python numeric separators, no letter segment + ("mask = 0x_123456\n", False), # hex literal + ("oasis-200401-wss-wssecurity-secext-1.0.xsd\n", False), # hyphen-joined: 11 measured hits + ("45 CFR 164-312 sandbox depth-100000\n", False), # hyphen-joined citations/constants + ("MSH|^~&|A|B|C|D|20260814120000||ADT^A01|ID|P|2.5\n", False), # HL7 timestamp + ("PID|1||123456^^^MRN||DOE^JANE\n", False), # HL7 caret-delimited field + ("WRITELOG 1234 ms 993496 tasks\n", False), # the DMV soak row the allowlist excuses + ("schema_version_20260814 = 1\n", False), # eight-digit dated identifier + ( + "PT__ADT_2 is the placeholder form\n", + False, + ), # the house stand-in must stay writable + (f"conn = 'PT_{_SYNTH_CODE}_ADT_2'\n", True), # the control: the real shape still fires + ): + hits = _shape_hits(mod, tmp_path, content, "docs/notes.md") + assert any(_SHAPE_REASON in h for h in hits) is expected, content + + +def test_estate_identifier_shape_is_not_gated_by_the_site_skip_suffixes( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """The skip sets exist because BARE digit runs storm in lock/SVG/password files. The underscore + anchor already removes that storm (measured: zero matches across those files), so applying the + skip here would buy nothing and open a hole -- a flame-graph SVG's frame labels are FUNCTION + NAMES, and a transform function name is one of the two forms this detector exists for.""" + mod = _load(None, monkeypatch) + assert mod.TOKENS_PRESENT is False, "precondition: structural-only" # type: ignore[attr-defined] + for name in ("requirements.lock", "art.svg", "common_passwords.txt"): + f = tmp_path / name + f.write_text(f"def xform_{_SYNTH_CODE}_to_erp_mfn\n", encoding="utf-8") + hits = mod.scan_file(f, f"docs/{name}") # type: ignore[attr-defined] + assert any(_SHAPE_REASON in h for h in hits), name + # ...while the site-code detectors' own skip is unchanged: a BARE run in these files is still + # waved through, which is the asymmetry this test pins. + f.write_text(f"standalone {_SYNTH_CODE} here\n", encoding="utf-8") + assert mod.scan_file(f, f"docs/{name}") == [], name # type: ignore[attr-defined] + + +def test_an_estate_shaped_file_NAME_is_flagged_by_the_path_alone( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """Half of what #321 found was a FILENAME, and a module need not repeat its own name in its text. + + The binary case is the sharp one, and it is why the check sits before the read: a DICOM or PDF + sample named with a site code is exactly as much of a leak as the .py beside it, and the content + scanner drops binaries unread. + """ + mod = _load(None, monkeypatch) + assert mod.TOKENS_PRESENT is False, "precondition: structural-only" # type: ignore[attr-defined] + text = tmp_path / "innocuous.py" + text.write_text("HANDLERS = ()\n", encoding="utf-8") + hits = mod.scan_file(text, f"samples/config/IB_FILE_HR_{_SYNTH_CODE}_MFN.py") # type: ignore[attr-defined] + assert len(hits) == 1, hits + assert ":0:" in hits[0], "a path-level finding has no line to point at and must say so" + + blob = tmp_path / "scan.dcm" + blob.write_bytes(b"\x00\x01\x02 not text at all") + assert mod.scan_file(blob, "samples/dicom/scan.dcm") == [] # type: ignore[attr-defined] + assert len(mod.scan_file(blob, f"samples/dicom/{_SYNTH_CODE}_scan.dcm")) == 1 # type: ignore[attr-defined] + + +def test_ordinary_paths_do_not_trip_the_estate_identifier_shape( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + """NEGATIVE CONTROL for the path arm. It is the arm with the smallest escape hatch -- the + ALLOWLIST is a per-line CONTENT veto and cannot reach a path finding, so the only remedy for a + false positive here is renaming a file. Measured zero over all tracked paths. + + Half the entries below carry a SIX-DIGIT RUN on purpose. No tracked path does today (measured: 0 + of 1955), so a table drawn only from real paths would hold under a detector with its anchor + deleted -- it would be a control that cannot fail, testing the corpus rather than the rule. These + are the near-miss shapes the repo's own conventions would produce first: a compressed benchmark + date, an eight-digit dated identifier, a hex-digest fixture name. + """ + mod = _load(None, monkeypatch) + f = tmp_path / "x.py" + f.write_text("clean\n", encoding="utf-8") + for rel, expected in ( + ("docs/adr/0166-sandbox-child-stderr-capture.md", False), + ("messagefoundry/store/sqlserver.py", False), + ("docs/benchmarks/results/2026-08-04/storedmv_soak.txt", False), + ("tests/test_scan_tokens_source.py", False), + ("harness/config/estate/_shape.py", False), + ("samples/config/IB_ACME_ADT_router.py", False), + ("docs/benchmarks/results/20260703-pooled/pooled_ab.json", False), + ("docs/benchmarks/results/2026-07-03/walk_console_20260703.txt", False), + ("tests/fixtures/hashes/aff07c990123ff.json", False), + # The control. Without it a detector that matched NOTHING would pass this test unchanged. + (f"samples/config/IB_FILE_{_SYNTH_CODE}_MFN.py", True), + ): + assert bool(mod.scan_file(f, rel)) is expected, rel # type: ignore[attr-defined] + + +def test_the_estate_identifier_shape_detector_is_live(monkeypatch: pytest.MonkeyPatch) -> None: + """Guard the detector itself. NO floor mechanism counts a structural detector -- ``_FLOOR_SECTIONS`` + counts token-source sections -- so if a future edit degrades this one to the module's own + never-matching sentinel, nothing else notices and every test above passes vacuously for the wrong + reason (the same shape of defect as a gate reporting clean because it read nothing).""" + mod = _load(None, monkeypatch) + assert mod._ESTATE_ID_SHAPE is not mod._NEVER # type: ignore[attr-defined] + assert mod._ESTATE_ID_SHAPE.search(f"PT_{_SYNTH_CODE}_ADT") is not None # type: ignore[attr-defined] + + +def test_allowlist_rejects_an_entry_broad_enough_to_disable_the_estate_shape( + tmp_path: Path, +) -> None: + """An allowlist entry is a per-line veto applied BEFORE every detector, so one over-broad line + switches the whole gate off while the loaded-counts diagnostic still reads healthy. + + The pre-existing canaries rejected a bare six-digit quantifier but ACCEPTED the underscore-joined + form, which is exactly the shape someone would reach for to excuse one estate-shape false positive + -- and it would veto every line joining a digit run to an identifier. The narrow entry is the + control: a validator that rejected everything would look identical to a working one. + """ + import importlib.util + import shutil + + dst = tmp_path / "security" + shutil.copytree(_ROOT / "scripts" / "security", dst) + _D6 = chr(92) + "d{6}" # built from parts so no line here is itself an allowlist-shaped literal + for entry, keep in ((_D6 + "_", False), ("_" + _D6, False), ("^HANDBACK_" + _D6 + "$", True)): + (dst / "scan-allowlist.txt").write_text(entry + "\n", encoding="utf-8") + spec = importlib.util.spec_from_file_location( + f"al_{next(_counter)}", dst / "scan_forbidden.py" + ) + assert spec is not None and spec.loader is not None + mod = importlib.util.module_from_spec(spec) + spec.loader.exec_module(mod) + assert bool(mod.ALLOWLIST) is keep, entry # type: ignore[attr-defined] From a113717b1f7dbcbac8d64524c82d3910583e2654 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 19:03:16 -0500 Subject: [PATCH 04/16] feat(sandbox): capture the child's stderr and relay it attributed, content below INFO (BACKLOG #343) The worker was spawned with stderr=None, so the child's stderr WAS the engine's own stderr, inherited raw. fd 1 is strictly framed; fd 2 had no discipline at all. Admin-authored Handler code could write arbitrary bytes into the operator's log of record -- forged engine lines, control sequences, or a printed message body. Both halves are conditional, not live: zero deployments, so a deploying site WOULD inherit this on first deployment. CONTENT RELAYS AT DEBUG AND ONLY DEBUG. At INFO and above the engine emits an attributed, rate-limited notice carrying identity and a COUNT and no content, so CLAUDE.md section 9 holds BY CONSTRUCTION rather than by operator discipline: there is no call site at which child stderr content becomes a record above DEBUG. The per-line byte cap was rejected in ADR 0166 for a reason specific to this payload -- truncating an HL7 v2 message to its first N bytes keeps MSH and PID, so it preserves precisely the most identifying part of the record. THE DEADLOCK THIS CREATES IS CLOSED IN THE SAME COMMIT. stderr=PIPE with no drainer blocks a flooding child, and the window that matters is bootstrap, where load_config() runs untrusted admin code before the boot reply is read. The relay thread starts in the same window the frame reader does. IDENTITY IS (inbound, pid, generation), NOT pid. An OS recycles pids, and the design turns on a stale generation's relay still draining a killed child while the live one runs. THE LINE CAP IS A MEMORY BOUND, NOT A REDACTION. A Handler can write megabytes with no newline, and an unbounded carry lets the child size the parent's heap. Reaching it splits one write across several DEBUG records and DISCARDS NOTHING, which is what distinguishes it from the rejected byte cap. PHI redaction is NOT reimplemented here -- it is a property of the log handlers this relay rides like any other record, and a second call site would be the drift SDS-3.5 warns about. Control-character scrubbing IS applied at this seam, because "one child write is one log record" is the relay's own framing contract and must not depend on how a host configured logging. ADR 0166 IS CORRECTED BY THIS BUILD, and the correction is the useful part: the draft claimed the stdout rebind leaves fd 1 "exclusively for frames". IT DOES NOT. Rebinding the NAME sys.stdout does not seal the descriptor -- sys.__stdout__.buffer, os.write(1, ...) and open(1, "wb") all still reach it. What keeps a raw writer harmless is unchanged: the closed-tag codec and the parent's unsolicited-frame check. Claiming the rebind sealed fd 1 would have been a compensating control resting on a false premise (SDS-3.7); what it actually buys is that the ACCIDENTAL case, print() in a Handler, can no longer sit one buffering change away from corrupting a frame. The ADR's attribution site is also corrected -- the identity is plumbed from RegistryRunner._sandbox_for in pipeline/wiring_runner.py, NOT engine.py, which builds only the policy and the config source -- and its line-number citations are replaced with symbol references, because a line anchor goes stale the moment the code it points at moves. Three consequences the ADR did not originally carry, each recorded when the build measured it: the drain is EOF-driven rather than cooperatively stopped (closing a pipe under a mid-read thread raises ValueError past an except OSError); close() takes a BOUNDED join, because this drain calls into logging and can be inside a handler's emit when logging.shutdown runs at exit; and the relay being the sole drainer makes a stalled off-box log collector back-pressure on a DEBUG-level child. Verified: mypy strict clean over 266 source files, ruff check and format clean over messagefoundry and tests, 87 passed across test_sandbox, test_sandbox_worker_logging, test_accepts_seam and test_phi_logging_inventory, in the lane venv built against constraints.lock. --- docs/CONFIGURATION.md | 15 +- docs/PHI.md | 33 +- docs/adr/0087-sandbox-subprocess-isolation.md | 16 +- ...captured-and-relayed-content-below-info.md | 102 ++++- docs/adr/README.md | 2 +- messagefoundry/last_resort.py | 13 +- messagefoundry/logging_setup.py | 23 +- messagefoundry/pipeline/_sandbox_worker.py | 48 ++- messagefoundry/pipeline/sandbox.py | 245 ++++++++++- messagefoundry/pipeline/wiring_runner.py | 6 +- tests/test_accepts_seam.py | 2 + tests/test_phi_logging_inventory.py | 33 +- tests/test_sandbox.py | 393 +++++++++++++++++- tests/test_sandbox_worker_logging.py | 56 +++ 14 files changed, 917 insertions(+), 70 deletions(-) diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index 086d66fc6..a28a4c64c 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -856,8 +856,19 @@ now reaps its whole process tree (a Windows kill-on-close job object / a POSIX p a grandchild no longer outlives the kill (BACKLOG #342). That reap is best-effort process hygiene: what makes a stray frame *harmless* is still the codec plus the request-answer binding (a live grandchild can force a respawn, i.e. dead-letter messages on that inbound, but nothing more), not the process teardown. -The child's **stderr is inherited by the engine**, so a -Handler that prints goes into the engine's log unparsed and un-redacted. ADR 0072 Router/Handler +The child's **stderr is captured by the engine, not inherited** (ADR 0166): a Handler that prints is +relayed into the engine's log attributed to the inbound, the child pid and the worker generation, with +**the content itself only at `DEBUG`**. At `INFO` and above you get a rate-limited `WARNING` naming the +inbound and counting the lines, and no content — that is deliberate, and it is how the never-log-bodies +rule is kept when a Handler prints a message body. To read what a Handler actually wrote, set +`[logging].level = "DEBUG"`, and treat that log as PHI-bearing while you do. Two things that will +surprise you otherwise: raising the level shows every `print` and raw write **plus** the child's own +`WARNING`+ records, but never the child's own `DEBUG`/`INFO` records — the worker's root logger is +pinned at `WARNING` when it starts and no knob plumbs a level into it (an unfiled follow-up, named by +subject rather than by a number that does not exist yet). And because that one relay thread is also +what keeps the child's stderr pipe from filling, a slow log handler — an off-box `[logging].forward_*` +collector that has stalled, say — becomes back-pressure on a `DEBUG`-level child rather than lost +output. ADR 0072 Router/Handler tracing does not compose with `mode=subprocess` (the sandbox branch precedes the tracer branch), and a `mode=subprocess` graph cannot use the ADR-0071 fused thread-hop path (it is hard-disabled). diff --git a/docs/PHI.md b/docs/PHI.md index 5207f541e..7f8d6cbd2 100644 --- a/docs/PHI.md +++ b/docs/PHI.md @@ -1029,12 +1029,33 @@ of the filters above. It is **out of scope for this section** — but treat a [§2](#2-where-phi-lives--data-at-rest-inventory). The **opt-in ADR 0087 sandbox worker** (`[sandbox].mode = "subprocess"`, default `"off"`) is **not** an -exclusion. The child is spawned with `stderr=None`, so it **inherits the engine's stderr** — stream 1's -own sink — and it installs the three filters above on that stream itself, via `configure_stderr_logging` -(BACKLOG #1054). A `WARNING`+ record emitted in the child by admin-authored Router/Handler code, or by a -library it pulls, is therefore redacted and CR/LF-scrubbed on the same terms as an engine record. -Redaction is a property of the **handler**, so this is a second installation of the chain rather than -something the child inherits along with the file descriptor. +exclusion, and this paragraph is the single statement of how its output reaches stream 1 — the code +docstrings link here rather than restate it. Two independent mechanisms cover it: + +- **Inside the child.** It calls `configure_stderr_logging`, which installs the same three filters on + its own stderr handler (BACKLOG #1054), so a `WARNING`+ record emitted there by admin-authored + Router/Handler code, or by a library it pulls, is redacted and CR/LF-scrubbed at the source. + Redaction is a property of the **handler**, so this is a second installation of the chain rather + than something the child inherits along with a file descriptor. +- **In the engine parent (ADR 0166, BACKLOG #343).** The child is spawned with + `stderr=subprocess.PIPE` — it no longer *inherits* stream 1's sink — and a per-worker drain thread + turns those bytes into engine log records attributed to the inbound, the child pid and the worker + generation. **Content is relayed at `DEBUG` and only at `DEBUG`.** At `INFO` and above the engine + emits an attributed, rate-limited `WARNING` notice carrying the identity and a line **count** and no + content, so the never-log-bodies rule holds **by construction**: a Handler that `print()`s a message + body cannot put that body on a default-level log, because no call site above `DEBUG` carries child + stderr content at all. Suppressed lines are counted and reported by the next notice, never dropped + silently. Relayed records ride stream 1's own handlers, so they are redacted and scrubbed on + stream 1's terms; the relay additionally scrubs control characters itself, because "one child write + is one log record" is the drain's own framing contract and cannot depend on the host process's + logging configuration. **Residuals, stated rather than implied — at least these:** raising the service to `DEBUG` + to read that content puts full Handler output on stream 1, at stream 1's PHI class — the same + posture as any `DEBUG` run; and the child's own root logger is pinned at `WARNING` when the worker + starts, so `DEBUG` shows every `print`/raw write plus the child's `WARNING`+ records, and never the + child's own `DEBUG`/`INFO` records, which the child never emitted. **A byte-cap truncation was + rejected, not overlooked:** truncating an HL7 v2 message to its first N bytes keeps MSH and PID and + discards the clinically bulky remainder, so it preserves precisely the most identifying part of the + record (ADR 0166). --- diff --git a/docs/adr/0087-sandbox-subprocess-isolation.md b/docs/adr/0087-sandbox-subprocess-isolation.md index af098ebd4..fc482cfbc 100644 --- a/docs/adr/0087-sandbox-subprocess-isolation.md +++ b/docs/adr/0087-sandbox-subprocess-isolation.md @@ -345,9 +345,19 @@ exotic object now reports a *codec* rejection rather than the pickle error text not change that — `mode=off` shares an address space too — and any claim that the pipe protects handler-to-handler integrity is false. The boundary drawn here is between admin code and the **engine**. Per-Handler confinement would need a worker per Handler. -- **The child's stderr is inherited by the engine** (`stderr=None`), unframed and unparsed: a - sandboxed Handler that prints writes straight into the engine's log. That is a log-injection / - PHI-to-log surface, not a frame surface. +- **The child's stderr is captured and relayed, no longer inherited** — closed by + [ADR 0166](0166-sandbox-child-stderr-is-captured-and-relayed-with-content-confined-below-info.md) + (BACKLOG #343). It was `stderr=None`, so a sandboxed Handler that printed wrote unframed and + unattributed straight into the engine's log: a log-injection / PHI-to-log surface, not a frame + surface. It is now `stderr=PIPE` drained by a per-worker thread, attributed to the inbound and + worker generation, with content confined to `DEBUG` and a counted notice above it. **New residuals + include at least:** + fd 1 is still reachable by a raw writer (the codec plus the unsolicited-frame check remain the + control, not the `sys.stdout` rebind); an embedded host that never called `configure_logging` gets + relayed `DEBUG` content on whatever handlers it built, exactly as it does for any engine record; the + relay is the sole drainer, so a slow log handler becomes back-pressure on a `DEBUG`-level child; and + attribution is per worker generation, not per Handler — one worker serves all of an inbound's + Handlers. - **ADR 0072 tracing does not compose with `mode=subprocess`.** In `_accepted`/`route_only`/ `transform_one` the sandbox branch precedes the tracer branch, so a traced dry-run produces no Router/Handler trace when the sandbox is on. It composes with `mode=off` as stated above. diff --git a/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md b/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md index 414828b22..ebf0a2ec9 100644 --- a/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md +++ b/docs/adr/0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md @@ -10,9 +10,9 @@ ## Context -**fd 1 is strictly framed. fd 2 has no discipline at all.** The sandbox worker is spawned at -[`pipeline/sandbox.py:442-450`](../../messagefoundry/pipeline/sandbox.py) with `stdout=PIPE` and -`stderr=None`. The `None` is load-bearing and was deliberate — its comment reads *"let the child's +**fd 1 is strictly framed. fd 2 has no discipline at all.** The sandbox worker was spawned in +[`pipeline/sandbox.py`](../../messagefoundry/pipeline/sandbox.py) (`SandboxSession._spawn`) with +`stdout=PIPE` and `stderr=None`. The `None` was load-bearing and deliberate — its comment reads *"let the child's stderr (logging) pass through to the engine's stderr"* — but the consequence is that the child's stderr **is** the engine's own stderr, inherited raw. Admin-authored Handler code therefore writes directly into the engine's log stream, unframed and unattributed. @@ -46,9 +46,23 @@ nothing pins. Leaving it is leaving a latent frame corruption behind a coinciden **D1 — Capture the child's stderr and relay it through the engine's stdlib logger.** Spawn with `stderr=subprocess.PIPE` and drain it on a dedicated reader thread, mirroring the existing stdout -frame reader at [`sandbox.py:495`](../../messagefoundry/pipeline/sandbox.py). Every relayed line is -attributed to the inbound and worker that produced it, sanitised of ANSI and other control bytes, and -rate-limited, with the suppression count reported rather than silently dropped. +frame reader at [`sandbox.py`](../../messagefoundry/pipeline/sandbox.py) (`_reader_loop`). Every +relayed line is attributed to the inbound, the child pid and a per-session **worker generation** +counter — a pid alone is not a unique identity, because an OS recycles pids and a stale generation's +relay can still be draining a killed child while the live one runs. Control bytes are neutralised by +`logging_setup.scrub_control_chars`, the **one** definition `ControlCharScrubFilter` already applies to +every record, called here at the point a byte stream is assembled into a record rather than +reimplemented beside it. Lines are rate-limited, with the suppression count reported rather than +silently dropped. + +**One bound in D1 must not be confused with the byte cap rejected below.** A child can write megabytes +with no newline, and an unbounded carry would let it size the parent's heap, so the drain splits a run +that reaches a fixed length into several records. That is a **memory** bound on the parent and it +**discards nothing** — every byte is still relayed, across more records. The rejected cap discards, and +discards the wrong end. + +PHI redaction is deliberately **not** a second call site here: it is a property of the engine's log +handlers, which this parent-side relay rides like any other record. **D2 — Content is relayed at DEBUG only. At INFO and above, the engine emits an attributed, rate-limited NOTICE carrying the identity and a count, and no content.** This is the load-bearing @@ -58,11 +72,30 @@ record at INFO or above, because no such call site exists. An operator running a *that* a given inbound's Handler is writing to stderr, and how much, which is the operationally actionable part. -**D3 — The worker rebinds `sys.stdout` to fd 2 at bootstrap, leaving raw fd 1 exclusively for -frames.** Sequenced after the frame writer captures its raw handle and before `load_config()` runs -any admin-authored code — which the comment at -[`sandbox.py:452-455`](../../messagefoundry/pipeline/sandbox.py) already identifies as the earliest -untrusted code and the first opportunity to spawn a grandchild. +**Built with two independent mechanisms, and the redundancy was measured rather than assumed.** The +sole content call site is `log.debug`, and it additionally sits behind an `isEnabledFor(DEBUG)` guard so +the bytes are never even decoded below that level. Breaking *either* alone still keeps a printed message +body off an INFO log; only breaking both puts one there. That is why the guard is worth its line despite +looking redundant next to a `log.debug`: it is what makes the property survive a later edit that raises +the call site, which is the realistic way this regresses. + +**The notice level is `WARNING`, not `INFO`.** An operator running `[logging].level = WARNING` would +never see an INFO notice, and a printing Handler would be entirely invisible — the accept-and-drop shape +the count-and-log invariant forbids, reintroduced by the fix for it. Cry-wolf is answered by the +throttle rather than by the level. + +**D3 — The worker rebinds `sys.stdout` to stderr at bootstrap, so the text layer cannot reach fd 1.** +Sequenced after the frame writer captures its raw handle and before `load_config()` runs any +admin-authored code — which the job-assignment comment in +[`sandbox.py`](../../messagefoundry/pipeline/sandbox.py) already identifies as the earliest untrusted +code and the first opportunity to spawn a grandchild. + +**This is design intent, not an enforced invariant, and the difference matters (SDS-3.7).** Rebinding +the *name* `sys.stdout` does not make fd 1 frames-only: `sys.__stdout__.buffer`, `os.write(1, ...)` and +`open(1, "wb")` all still reach the raw descriptor. What keeps a raw writer harmless is unchanged — the +closed-tag codec and the parent's unsolicited-frame check. Claiming the rebind seals fd 1 would be a +compensating control resting on a false premise; what it actually buys is that the *accidental* case +(`print()` in a Handler) can no longer sit one buffering change away from corrupting a frame. ## Alternatives rejected @@ -95,18 +128,47 @@ stderr reader must therefore start in the same window the stdout reader does — write — and no spawn or error path may leave a `PIPE` undrained. **This hazard did not exist before this decision.** -**Attribution requires plumbing the engine does not have today.** `SandboxRunner` holds its policy, -config directory and environment, but no inbound name. Attributing a relayed line to an inbound -therefore widens the change beyond `sandbox.py` into the construction site in `engine.py`. That cost -is accepted: an unattributed relay closes (b) and leaves (a) open, and (a) is the forgery half. +*Measured while building it* (1 MiB written from config module scope, `startup_seconds = 10`): the +spawn wedges for the full startup budget when the drain starts after the boot **reply** is read, and +does **not** wedge when it starts immediately after the boot frame **write**, because the parent then +blocks on the reply while the drain is already running. The rule above is stated at the stricter of the +two on purpose — the safe boundary is cheap, the failure is a startup timeout that names the wrong +cause, and the margin is whatever a future edit inserts between the two points. -**A second reader thread is a second teardown obligation.** It must be daemonised, cooperatively -stopped, and torn down on respawn and on close alongside the existing reader, or a killed worker -generation leaks a thread holding a dead pipe. +**Attribution requires plumbing the engine does not have today.** `SandboxSession` holds its policy, +config directory and environment, but no inbound name. Attributing a relayed line to an inbound +therefore widens the change beyond `sandbox.py` into the sole production construction site, +`RegistryRunner._sandbox_for` in `pipeline/wiring_runner.py` — **not** `engine.py`, which builds only +the policy and the config source. That cost is accepted: an unattributed relay closes (b) and leaves +(a) open, and (a) is the forgery half. The parameter is **required and keyword-only**, so a future +caller that forgets it fails at type-check time rather than silently reinstating an unattributed relay. + +**A second drain thread is a second teardown obligation, and it is EOF-driven rather than +cooperatively stopped.** There is no stop flag to set: the drain is blocked in `read()` on the child's +pipe, and what ends it is the pipe reaching EOF when `_kill` reaps the whole process tree — the same +reap that already EOFs fd 1. Neither pipe is closed to force it, because closing a file object under a +mid-read thread raises `ValueError`, which neither drain's `except OSError` catches, so it would escape +into `threading.excepthook`. The respawn path therefore does **not** join: a surviving grandchild holds +both pipes, and waiting on it under the session lock would wedge the feed. `close()` is the one +exception and takes a **bounded** join, because this drain — unlike the frame reader, which only +enqueues — calls into `logging`, and a daemon thread inside a handler's `emit` when `logging.shutdown` +runs at exit either writes to a closed stream or holds a lock the atexit hook then blocks on. + +**The relay is the sole drainer, so a slow log handler becomes back-pressure on the child.** A stalled +`[logging].forward_*` TCP/TLS collector makes each relayed record block for the forward timeout; a +blocked relay stops draining; a full pipe blocks the child mid-dispatch until `wall_seconds` fires and +the message dead-letters. This is back-pressure and not loss, and it only arises at `DEBUG`, where +content is being relayed at all — but it is a coupling that `stderr=None` did not have, and it belongs +here rather than in an incident. **Operators running at INFO lose Handler stdout and stderr content.** This is the deliberate cost of -D2 and should be stated in the operator documentation rather than discovered. The notice tells them -the content exists and at which level to find it. +D2 and is stated in [docs/CONFIGURATION.md](../CONFIGURATION.md) rather than left to be discovered. +The notice tells them the content exists and at which level to find it. One caveat travels with that +instruction: `configure_stderr_logging` pins the **child's** root logger at `WARNING` for the worker's +whole life, and raising the parent's level does not reach it, so `DEBUG` yields every `print` and raw +write plus the child's `WARNING`+ records, and never the child's own `DEBUG`/`INFO` records — which the +child never emitted. Plumbing a level into the boot frame would add a wire field and is left as an +unfiled follow-up, named by subject because no number is allocated for it. ## References diff --git a/docs/adr/README.md b/docs/adr/README.md index ac120668e..25c6aa1bc 100644 --- a/docs/adr/README.md +++ b/docs/adr/README.md @@ -195,4 +195,4 @@ what is withheld and what you can request. | [0170](0170-constant-work-recovery-code-verification-pad-to-the-configured-slot-count-rather-than-short-circuit.md) | **Constant-work recovery-code verification: pad to the configured slot count rather than short-circuit** (BACKLOG #1167, ASVS 11.2.4) -- `_verify_second_factor` walked the argon2id recovery-code hashes and `return`ed on the first match, so the NUMBER of ~64 MiB verifications was a function of which code was presented. **Two leaks and only one matters:** the matched INDEX is worthless (the attacker holds the code and the response answers them anyway), but on the FAILURE path the cost is one verify per REMAINING code -- so anyone holding the password can time a wrong-code refusal and learn how many recovery codes an account has left, without authenticating to the second factor. **The item rated this difficulty 7 on a premise that does not survive measurement:** the re-score says a constant loop 'converts a timing leak into a memory and CPU amplification target', which is the right objection to raise -- and the failure path ALREADY verifies every remaining hash, so making the walk unconditional introduces no new cost, it makes today's WORST CASE the only case. Decision: always run exactly `mfa_recovery_code_count` verifies, padding with the same fixed `_DUMMY_PASSWORD_HASH` the local login leg uses, and select the winner AFTER the loop. Ceiling unmoved (default 10, validator-capped 50); `_argon2`'s semaphore means the concurrent-argon2 footprint cannot widen either; and the path sits behind primary authentication, so it is not an unauthenticated flood surface. **Claims constant WORK, not constant TIME** -- the store round trip on a match is not equalized, the TOTP branch returns earlier, and argon2's own constant-timeness is INHERITED from `argon2-cffi` and has never been measured in this tree, a gap #1167 names and this does not close. No timing measurement was run by the item or by this change. Rejected: leaving the short-circuit as accepted (the fix cost nothing against the existing ceiling, so 'accepted' would have been a judgement made before the amplification premise was checked); and a non-secret lookup index so only ONE verify ever runs -- strictly better on both axes, rejected as OUT OF SCOPE rather than wrong, needing a schema change across three backends and a migration, and recorded so it is not re-derived if the constant walk's cost ever bites | **Accepted (2026-08-22)** -- built with the change. Three parametrized tests pin the count for a first-slot match, a last-slot match and a non-match; proven red-first, removing the padding reds ALL THREE and the file restores byte-identical by SHA-256. Severity conditional per CLAUDE.md section 0 -- **zero deployments**, so this is what a first deployment would have inherited | | [0171](0171-offline-administrator-unlock-a-host-gated-cli-recovery-path-for-a-sole-administrator-lockout.md) | **Offline administrator unlock: a host-gated CLI recovery path for a sole-administrator lockout** (BACKLOG #1236) -- a deployment with ONE administrator had no recovery from account lockout, and every exit is individually deliberate: the bootstrap account is literally `admin`, it is created with no email so the ACCOUNT_LOCKED notice never leaves the process, self-reset is refused, an admin reset needs ANOTHER admin, re-bootstrap fires only on an EMPTY users table, and none of 38 CLI subcommands managed users. **The defect is that they close SIMULTANEOUSLY for that deployment** and nothing notices the conjunction. **The filed acceptance criterion could not discriminate and was amended 2026-08-21:** "recover without hand-editing the database and without a second admin" PASSES ON THE SHIPPED SYSTEM BY WAITING, since the lock self-expires after `lockout_minutes`; a test both a fixed and a broken system pass is not a test. Decision: `messagefoundry admin-unlock --username `. **The gate is HOST ACCESS and it is a real gate rather than an absent one** -- reaching it needs the config, the store path and on an encrypted store the key material, so anyone holding all three already has the database and does not need an unlock to reach an account; that is why it ships unauthenticated, and it is the load-bearing claim. **Clears the lockout and does NOT reset the password** -- deliberately narrower, since a reset would hand the runner a working account. **Reuses `record_login_failure(failed_attempts=0, locked_until=None)` rather than adding a protocol method**, decided by a MEASURED cross-lane fact rather than taste: a named `clear_lockout` would touch base/store/postgres/sqlserver, and all four were uncommitted in a peer lane at the time, so reuse avoided a four-file collision. Exit codes follow the `--json` convention (`_emit_error`, 1) not the M-31 lineage (stderr, 2), verified against `audit-verify` which has no `--json` flag. Carries M-31 forward: a typo'd `--db` is refused rather than creating an empty SQLite store and reporting a false "no such account" | **Accepted (2026-08-22)** -- built with the change. Four tests; **exactly ONE is the control** and the other three are deliberately insensitive -- neutering the clearing call reds only the acceptance test, and the audit-row test still passes under that plant, so it evidences the flow RAN and never that it WORKED. Does NOT address #1236's repetition limb: lock cycles remain unbounded and an attacker can re-lock. Severity conditional per CLAUDE.md section 0 -- **zero deployments** | | [0173](0173-tls-peer-revocation-checking-and-ocsp-stapling-across-terminating-and-originating-surfaces.md) | **TLS peer revocation checking and OCSP stapling across terminating and originating surfaces** (BACKLOG #1005, ASVS 12.1.4) -- the requirement reaches in two directions and the engine answers neither: where the product TERMINATES TLS it does not staple its own certificate's status, and where it ORIGINATES it does not check the peer's revocation. Direction 1 is RUNTIME-BLOCKED rather than unbuilt -- CPython 3.14.6 exposes no stapling surface at all, measured against live positive controls, so no amount of engineering here reaches it. The opt-in client-certificate CRL checking that DOES ship (`config/tls_policy.py:215-276`, three PROTOCOL_TLS_SERVER call sites) is a THIRD combination -- peer revocation on the terminating side -- and moves neither graded direction; that is the single easiest thing in this area to misread. DECISION: accept and document both directions, with one build rider the accept reasoning does not cover -- three originating hops that never reach the existing revocation guard, filed by subject and deliberately unallocated. | **Proposed (2026-08-23)** -- no code changed. Severity is conditional per CLAUDE.md section 0: on a first deployment a revoked partner certificate would keep verifying on the unguarded hops; there are zero deployments today. Five citation errors from the adversarial pass were repaired before filing. | -| [0176](0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md) | **Sandbox child stderr is captured and relayed, with content confined below INFO** (BACKLOG #343) — the sandbox worker is spawned with `stderr=None` (`pipeline/sandbox.py:446`), so **fd 1 is strictly framed and fd 2 has no discipline at all**: the child's stderr *is* the engine's stderr, inherited raw, and admin-authored Handler code writes straight into the operator's log of record (NSSM captures it to files). Two problems with different severities live in that one fact — **(a) attribution**, a Handler line being byte-indistinguishable from an engine line, hence forgeable log lines and ANSI control sequences; and **(b) PHI**, a Handler `print()`ing a message body writing a full payload into the general log, which CLAUDE.md section 9 forbids at INFO and above. Both are **conditional, not live** (section 0: zero deployments) — a deploying site would inherit them on first deployment. **Decision:** capture with `stderr=PIPE` and relay on a dedicated reader thread mirroring the existing frame reader, attributed, ANSI-sanitised and rate-limited with the suppression count reported; **relay CONTENT at DEBUG only, and at INFO and above emit an attributed rate-limited NOTICE carrying identity and a count and no content**, which satisfies section 9 **by construction** rather than by operator discipline because no INFO-or-above call site carrying content exists; and rebind the worker's `sys.stdout` to fd 2 at bootstrap, after the frame writer captures its raw handle and before `load_config()` runs untrusted code, closing the adjacent latent frame corruption that survives today **by buffering luck rather than design**. **The rejected alternative is the instructive one: relay at INFO with a per-line byte cap.** It fails on the shape of this payload specifically — **truncating an HL7 v2 message to its first N bytes keeps MSH and PID**, the header and the patient identifying segment, discarding the clinically bulky remainder, so a byte cap preserves *precisely* the most identifying part. It is the **worst available redaction for this format**, not merely a weak one, and would place a section 9 violation inside the fix for the defect that violation is about. Also rejected: `DEVNULL` (closes both problems, costs every Handler traceback) and prose-only documentation (a compensating control resting on nothing, the SDS-3.7 shape). **Consequence stated rather than softened: this decision CREATES a deadlock hazard that did not previously exist** — `stderr=PIPE` with no drainer blocks a flooding child, and the window that matters is bootstrap, where `load_config()` runs untrusted code before the boot reply is read, so the stderr reader must start in the same window the stdout reader does and no error or respawn path may leave a PIPE undrained. Attribution also **widens the diff beyond `sandbox.py`**: `SandboxRunner` holds no inbound identity today, so it must be plumbed from `engine.py` — accepted, because an unattributed relay closes (b) and leaves (a), the forgery half, open | **Proposed (2026-08-14)** — engine change being built against it under BACKLOG #343 | +| [0176](0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md) | **Sandbox child stderr is captured and relayed, with content confined below INFO** (BACKLOG #343) — the sandbox worker is spawned with `stderr=None` (`pipeline/sandbox.py:446`), so **fd 1 is strictly framed and fd 2 has no discipline at all**: the child's stderr *is* the engine's stderr, inherited raw, and admin-authored Handler code writes straight into the operator's log of record (NSSM captures it to files). Two problems with different severities live in that one fact — **(a) attribution**, a Handler line being byte-indistinguishable from an engine line, hence forgeable log lines and ANSI control sequences; and **(b) PHI**, a Handler `print()`ing a message body writing a full payload into the general log, which CLAUDE.md section 9 forbids at INFO and above. Both are **conditional, not live** (section 0: zero deployments) — a deploying site would inherit them on first deployment. **Decision:** capture with `stderr=PIPE` and relay on a dedicated reader thread mirroring the existing frame reader, attributed, ANSI-sanitised and rate-limited with the suppression count reported; **relay CONTENT at DEBUG only, and at INFO and above emit an attributed rate-limited NOTICE carrying identity and a count and no content**, which satisfies section 9 **by construction** rather than by operator discipline because no INFO-or-above call site carrying content exists; and rebind the worker's `sys.stdout` to fd 2 at bootstrap, after the frame writer captures its raw handle and before `load_config()` runs untrusted code, closing the adjacent latent frame corruption that survives today **by buffering luck rather than design**. **The rejected alternative is the instructive one: relay at INFO with a per-line byte cap.** It fails on the shape of this payload specifically — **truncating an HL7 v2 message to its first N bytes keeps MSH and PID**, the header and the patient identifying segment, discarding the clinically bulky remainder, so a byte cap preserves *precisely* the most identifying part. It is the **worst available redaction for this format**, not merely a weak one, and would place a section 9 violation inside the fix for the defect that violation is about. Also rejected: `DEVNULL` (closes both problems, costs every Handler traceback) and prose-only documentation (a compensating control resting on nothing, the SDS-3.7 shape). **Consequence stated rather than softened: this decision CREATES a deadlock hazard that did not previously exist** — `stderr=PIPE` with no drainer blocks a flooding child, and the window that matters is bootstrap, where `load_config()` runs untrusted code before the boot reply is read, so the stderr reader must start in the same window the stdout reader does and no error or respawn path may leave a PIPE undrained. Attribution also **widens the diff beyond `sandbox.py`**: `SandboxSession` holds no inbound identity today, so it must be plumbed from its sole production construction site, `RegistryRunner._sandbox_for` in `pipeline/wiring_runner.py` (**not** `engine.py`, which builds only the policy and the config source) — accepted, because an unattributed relay closes (b) and leaves (a), the forgery half, open. Three consequences the decision did not originally carry, each recorded when the build measured it: the drain is **EOF-driven rather than cooperatively stopped** (the reap that already EOFs fd 1 ends it; neither pipe is closed, because closing one under a mid-read thread raises `ValueError` past an `except OSError`), `close()` takes a **bounded** join because this drain — unlike the frame reader, which only enqueues — calls into `logging` and can be inside a handler's `emit` when `logging.shutdown` runs at exit, and the relay being the **sole drainer** makes a stalled off-box log collector back-pressure on a `DEBUG`-level child | **Proposed (2026-08-14)** — engine change being built against it under BACKLOG #343 | diff --git a/messagefoundry/last_resort.py b/messagefoundry/last_resort.py index 98819d288..1fd74d123 100644 --- a/messagefoundry/last_resort.py +++ b/messagefoundry/last_resort.py @@ -68,11 +68,14 @@ def _thread_excepthook(args: threading.ExceptHookArgs) -> None: ``threading.excepthook`` and nowhere else — so the redaction guarantee already in force on the main thread must be installed a second time to reach the others (BACKLOG #1055). - The concrete engine thread is the sandbox session's raw stdout-reader daemon - (``SandboxSession._reader_loop``), whose ``except`` clause catches only ``OSError`` by design; - anything else escapes ``run()`` and lands here, and the frame bytes it was mid-read on are - message-derived. ``SystemExit`` is ignored exactly as the stdlib default ignores it — a thread - calling ``sys.exit()`` is a clean exit, not an error to report. + The concrete engine threads include **at least** the sandbox session's two per-worker daemon + drains — the raw stdout frame reader (``SandboxSession._reader_loop``) and the stderr relay + (``_StderrRelay.run``, ADR 0166) — each of whose ``except`` clauses catches only ``OSError`` by + design; anything else escapes ``run()`` and lands here, and the bytes either one was mid-read on + are message-derived. Both threads are named for their pipe, their inbound and their worker + generation, so ``args.thread.name`` below identifies which one died. ``SystemExit`` is ignored as the + stdlib default ignores it — a thread calling ``sys.exit()`` is a clean exit, not an error to + report. """ if args.exc_value is None or issubclass(args.exc_type, SystemExit): return diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index be25d433e..191f30f60 100644 --- a/messagefoundry/logging_setup.py +++ b/messagefoundry/logging_setup.py @@ -44,6 +44,7 @@ "set_runtime_level", "current_log_level", "silence_phi_prone_dependency_loggers", + "scrub_control_chars", "ControlCharScrubFilter", "RedactionFilter", "JsonFormatter", @@ -104,6 +105,18 @@ _CONTINUATION_PREFIX = " | " +def scrub_control_chars(text: str) -> str: + """Escape C0 control characters and DEL (tab kept as benign whitespace) so no part of ``text`` can + begin a new physical line or drive a terminal. + + The single definition of that translation. :class:`ControlCharScrubFilter` applies it to every + record on a configured handler; a caller that assembles a record's content from an untrusted BYTE + stream needs it at the point of assembly, because "one peer write is one log record" is that + caller's own framing contract and cannot depend on how the host process configured logging — today + the ADR 0166 sandbox stderr relay. Idempotent: the escaped forms contain no control characters.""" + return text.translate(_CTRL_TRANSLATION) + + def _scrub_block(text: str) -> str: """Escape control characters in a multi-line block (``exc_text``/``stack_info``) while KEEPING its line breaks, indenting every line with :data:`_CONTINUATION_PREFIX`. @@ -116,7 +129,7 @@ def _scrub_block(text: str) -> str: filter chain, so a record dispatched to stdout *and* the off-box forwarder is scrubbed twice and the two sinks must not disagree.""" return "\n".join( - _CONTINUATION_PREFIX + line.removeprefix(_CONTINUATION_PREFIX).translate(_CTRL_TRANSLATION) + _CONTINUATION_PREFIX + scrub_control_chars(line.removeprefix(_CONTINUATION_PREFIX)) for line in text.split("\n") ) @@ -138,7 +151,7 @@ class ControlCharScrubFilter(logging.Filter): def filter(self, record: logging.LogRecord) -> bool: message = record.getMessage() - scrubbed = message.translate(_CTRL_TRANSLATION) + scrubbed = scrub_control_chars(message) if scrubbed != message: record.msg = scrubbed record.args = () @@ -506,9 +519,9 @@ def configure_stderr_logging(level: int = logging.WARNING) -> logging.Handler: stream right and the *filters* wrong. It installs a handler with **no filters at all**, and redaction here is a property of the **handler**, not of the logger or the call site (see :func:`_install_phi_filters`), so a child that builds its own handler builds an unfiltered one - unless it asks for the chain: its records would reach the inherited stderr with neither PHI - redaction nor CR/LF neutralization (BACKLOG #1054). Every process that logs installs the chain, or - it does not have it. + unless it asks for the chain: its records would reach the stderr the parent captures and relays + (ADR 0166) with neither PHI redaction nor CR/LF neutralization (BACKLOG #1054). Every process that + logs installs the chain, or it does not have it. The text formatter is the shared one, so a child line is byte-compatible with the parent's and :class:`ControlCharScrubFilter`'s "no line may impersonate the record prefix" guarantee is stated diff --git a/messagefoundry/pipeline/_sandbox_worker.py b/messagefoundry/pipeline/_sandbox_worker.py index efa129252..9a7aedb41 100644 --- a/messagefoundry/pipeline/_sandbox_worker.py +++ b/messagefoundry/pipeline/_sandbox_worker.py @@ -24,12 +24,14 @@ The reply echoes the request's ``id``, ``phase`` and ``name`` so the parent can prove the frame answers the call it made. -stdout is the binary IPC channel — **nothing else may write to it**. Logging and any diagnostics go to -stderr (inherited by the engine) through the **same PHI-redaction + control-char-scrub filter chain the -engine installs on its own handlers** (:func:`~messagefoundry.logging_setup.configure_stderr_logging`), -so a child log line carrying message-derived content is redacted and CR/LF-neutralized here rather than -arriving raw on the inherited stream. The engine parent enforces the wall-clock cap and kills a runaway -child, so this process never needs its own watchdog. +stdout is the binary IPC channel — **nothing else may write to it**, and :func:`_redirect_stdout_to_stderr` +states that intent by pointing ``sys.stdout`` at stderr for the rest of the process (ADR 0166). Logging +and any diagnostics go to stderr — which the parent CAPTURES and relays, attributed, with content +confined below INFO — through the **same PHI-redaction + control-char-scrub filter chain the engine +installs on its own handlers** (:func:`~messagefoundry.logging_setup.configure_stderr_logging`), so a +child log line carrying message-derived content is redacted and CR/LF-neutralized here as well as on +the parent's own handlers. The engine parent enforces the wall-clock cap and kills a runaway child, so +this process never needs its own watchdog. """ from __future__ import annotations @@ -49,6 +51,36 @@ configure_stderr_logging() log = logging.getLogger("messagefoundry.sandbox.worker") +#: Keeps the startup ``sys.stdout`` wrapper alive for the process lifetime. Load-bearing, not +#: belt-and-braces: :func:`main` captures ``sys.stdout.buffer`` (the ``BufferedWriter``), which does +#: **not** keep its ``TextIOWrapper`` alive; after the rebind ``sys.__stdout__`` is the only other +#: reference, ``TextIOWrapper.__del__`` closes its buffer, and admin config -- which runs after the +#: rebind -- may assign ``sys.__stdout__``. A one-line ``sys.__stdout__ = None`` in a config module +#: would otherwise close fd 1 and make the next frame write raise ``ValueError``, which none of +#: :func:`main`'s ``except (OSError, SandboxError)`` clauses catch. +_ORIGINAL_STDOUT: Any = None + + +def _redirect_stdout_to_stderr() -> None: + """Point ``sys.stdout`` at ``sys.stderr`` so ordinary text output cannot reach fd 1 (BACKLOG #343). + + fd 1 is the MFW2 frame channel. A Handler's ``print()`` lands in the startup ``TextIOWrapper``'s + buffer while frames go through the underlying ``BufferedWriter``, so today it happens not to + corrupt a frame -- an artifact of two buffers over one descriptor that nobody chose and nothing + pins. Aliasing the NAME states the intent: text goes to stderr, where the parent's relay attributes + it and confines its content below INFO. + + Design intent, **not** an enforced invariant: ``sys.__stdout__.buffer``, ``os.write(1, ...)`` and + ``open(1, "wb")`` still reach fd 1. The closed-tag codec plus the parent's unsolicited-frame check + remain the control for a raw writer -- claiming fd 1 is enforced frames-only would be a + compensating control resting on a false premise (SDS-3.7). + + Not ``os.dup2(2, 1)``, which moves the DESCRIPTOR and would take the frame writer's own + ``BufferedWriter`` with it; not ``detach()``, which leaves ``sys.__stdout__`` unusable.""" + global _ORIGINAL_STDOUT + _ORIGINAL_STDOUT = sys.stdout + sys.stdout = sys.stderr + class _ForbiddenImportFinder: """A ``sys.meta_path`` finder that fails a forbidden import loudly. @@ -215,6 +247,10 @@ def main() -> int: stdin = sys.stdin.buffer stdout = sys.stdout.buffer + # Sequenced deliberately: AFTER the frame writer captures its raw handle (at module scope the + # capture above would resolve to fd 2 and send every frame to the wrong pipe) and BEFORE the boot + # frame read below, whose reply path runs ``load_config()`` -- the earliest untrusted code. + _redirect_stdout_to_stderr() frame = _read_frame_bytes(stdin) if frame is None: diff --git a/messagefoundry/pipeline/sandbox.py b/messagefoundry/pipeline/sandbox.py index 115f08aa1..f8d78c54f 100644 --- a/messagefoundry/pipeline/sandbox.py +++ b/messagefoundry/pipeline/sandbox.py @@ -82,13 +82,15 @@ import subprocess import sys import threading +import time from collections.abc import Callable, Mapping from dataclasses import dataclass from pathlib import Path -from typing import Any, Final +from typing import IO, Any, Final from messagefoundry.config.code_sets import CodeSet from messagefoundry.config.run_context import RunContext +from messagefoundry.logging_setup import scrub_control_chars from messagefoundry.pipeline import _sandbox_codec as codec from messagefoundry.pipeline._sandbox_codec import SandboxCodecError, SandboxError @@ -179,6 +181,163 @@ def __repr__(self) -> str: # pragma: no cover - diagnostics only _EOF: Final = _Eof() +# --- child stderr relay (BACKLOG #343, ADR 0166) ------------------------------ + +#: One ``read(2)``. The child is spawned with ``bufsize=0``, so ``proc.stderr`` is RAW: this is the +#: syscall size, not a buffer fill, and a short read is normal. Sized well above the line cap so a +#: flooding child costs syscalls proportional to volume, not to line count. +_STDERR_READ: Final = 65536 + +#: Longest run held while waiting for a newline. A MEMORY bound on the parent, never a redaction: a +#: Handler can write megabytes with no terminator, and an unbounded carry lets the child size the +#: parent's heap. Reaching it splits one write across several DEBUG records and DISCARDS NOTHING -- +#: which is exactly what distinguishes it from the per-line byte cap ADR 0166 rejected. That cap was +#: rejected for a reason specific to this payload: truncating an HL7 v2 message to its first N bytes +#: keeps MSH and PID -- the header and the patient identifiers -- and discards the clinically bulky +#: remainder, so it preserves precisely the most identifying part of the record. It is the worst +#: available redaction for this format, not merely a weak one. +_STDERR_LINE_CAP: Final = 8192 + +#: Floor between two stderr notice records for one worker generation. The notice is what an operator +#: at INFO gets INSTEAD of content, so it must not become the flood it reports. Lines inside a window +#: are COUNTED and carried by the next notice, so nothing is dropped silently. +_STDERR_NOTICE_SECONDS: Final = 60.0 + +#: How long :meth:`SandboxSession.close` waits for each drain thread. Bounded on purpose: a surviving +#: grandchild can hold the pipes open indefinitely, and this runs under the session lock. +_STDERR_JOIN_SECONDS: Final = 1.0 + + +class _StderrRelay: + """One worker GENERATION's stderr, turned into log records (BACKLOG #343, ADR 0166). + + Content at DEBUG and only DEBUG; at INFO and above an attributed, rate-limited notice carrying + identity and a COUNT and no content. CLAUDE.md section 9 holds here **by construction** rather than + by operator discipline: there is no call site at which child stderr content becomes a record above + DEBUG, so no configuration, verbosity setting or error path can put a printed message body on a + default-level log. The rejected per-line byte cap is recorded on :data:`_STDERR_LINE_CAP`. + + One instance per spawn, reachable only through its own daemon thread. A relay whose child was killed + can still be draining that child's buffered output while the next generation runs, so every counter + lives here rather than on the session: a respawn replaces the session's thread list and the stale + relay goes with it, unable to write into the live generation's state -- the same stale-generation + isolation the fresh :class:`queue.Queue` gives the frame reader. The notice budget therefore resets + on respawn; accepted, because a respawn costs a full ``load_config()``. + + PHI redaction is deliberately NOT re-implemented here. It is a property of the engine's log + HANDLERS (:func:`~messagefoundry.logging_setup._install_phi_filters`), which this parent-side call + site rides exactly like any other engine log record; a second call site would be the drift SDS-3.5 + warns about. Control-character scrubbing IS applied here, because "one child write is one log + record" is this class's own framing contract and must not depend on how the host process configured + logging (an embedded runner may carry plain handlers). The honest residual: in a host that never + called ``configure_logging``, relayed DEBUG content reaches that host's handlers unredacted -- + exactly as any engine log line does, not a new exclusion. Identity is ``(inbound, pid, + generation)``: pid alone is not unique, because an OS recycles pids and the whole design turns on a + stale generation's relay coexisting with the live one.""" + + __slots__ = ("_inbound", "_pid", "_gen", "_buf", "_pending", "_total", "_last_notice") + + def __init__(self, inbound: str, pid: int, generation: int) -> None: + self._inbound = inbound + self._pid = pid + self._gen = generation + self._buf = bytearray() + self._pending = 0 + self._total = 0 + self._last_notice: float | None = None + + def run(self, stream: IO[bytes]) -> None: + """Drain ``stream`` to EOF on a daemon thread. Never raises: an escaping exception would end + the drain, and a pipe nobody drains blocks the child once the OS buffer fills.""" + try: + while True: + chunk = stream.read(_STDERR_READ) + if not chunk: + break + self.feed(chunk) + except OSError: + pass # the pipe died with the worker; the kill path reports that, this thread does not + finally: + self.close() + + def feed(self, chunk: bytes) -> None: + """Accumulate ``chunk`` and emit every complete line (or cap-length run) it completes.""" + self._buf.extend(chunk) + while True: + newline = self._buf.find(b"\n") + # ``<=``, not ``<``: a terminator landing exactly ON the bound is a complete line of cap + # length, not an over-length run. Splitting there instead would consume the bytes and leave + # the newline to open the next pass, emitting a spurious empty record. + if 0 <= newline <= _STDERR_LINE_CAP: + line = bytes(self._buf[:newline]) + del self._buf[: newline + 1] + elif len(self._buf) >= _STDERR_LINE_CAP: + # No terminator within the bound: split rather than hold. Splitting mid-character is + # why the decode below is `errors="replace"` and not strict. + line = bytes(self._buf[:_STDERR_LINE_CAP]) + del self._buf[:_STDERR_LINE_CAP] + else: + return + self._line(line) + + def close(self) -> None: + """Flush a trailing unterminated write and force a final notice, so a child that exits + mid-line is still both relayed and counted.""" + if self._buf: + line = bytes(self._buf) + self._buf.clear() + self._line(line) + self._notice(force=True) + + def _line(self, line: bytes) -> None: + self._pending += 1 + self._total += 1 + self._notice(force=False) + if not log.isEnabledFor(logging.DEBUG): + # Section 9 rests on TWO independent facts, and this guard is only the second of them. + # First: the sole call site carrying content is the ``log.debug`` below, so raising the + # service level is the only way content becomes a record at all. Second: this guard, which + # means the bytes never even become a `str` below DEBUG -- so the property survives an edit + # that raises that call site, and no decode/scrub cost is paid on a flooding child. Both + # were measured: breaking either alone still keeps a printed body off an INFO log. + return + # `errors="replace"`, never strict: a decode raise here would kill the drain and re-create the + # deadlock this thread exists to prevent. Never latin-1 either -- it corrupts on NUL (CLAUDE.md + # section 8). + text = scrub_control_chars(line.removesuffix(b"\r").decode("utf-8", "replace")) + log.debug( + "sandbox stderr [%s pid %d gen %d]: %s", self._inbound, self._pid, self._gen, text + ) + + def _notice(self, *, force: bool) -> None: + """Report THAT the child wrote to stderr -- identity and counts, never content. + + WARNING, not INFO: an operator running ``[logging].level = WARNING`` would never see an INFO + notice, and a printing Handler would be completely invisible -- the accept-and-drop shape the + count-and-log invariant forbids, reintroduced by the fix for it. Cry-wolf is answered by the + throttle instead: one record per generation at first output, then at most one per window, and + worker spawns are per-inbound-per-reload rather than per-message.""" + if self._pending == 0: + return + now = time.monotonic() + throttled = ( + self._last_notice is not None and now - self._last_notice < _STDERR_NOTICE_SECONDS + ) + if not force and throttled: + return + lines, self._pending = self._pending, 0 + self._last_notice = now + log.warning( + "sandbox worker wrote to stderr [%s pid %d gen %d]: %d line(s) since the last notice, " + "%d total for this worker; content is relayed at DEBUG only (ADR 0166)", + self._inbound, + self._pid, + self._gen, + lines, + self._total, + ) + + def _write_frame(stream: Any, body: bytes) -> None: """Write one length-prefixed frame body. Raises on an over-cap frame (fail-closed) or a broken pipe; the caller maps either to :class:`SandboxError`.""" @@ -396,13 +555,19 @@ def __init__( self, policy: SandboxPolicy, *, + inbound: str, config_dir: str | Path, env: str | None, code_sets: Mapping[str, CodeSet] | None = None, ) -> None: self.policy = policy + # Required, with no default, deliberately: this is what attributes a relayed stderr line to a + # feed (ADR 0166), and a default would silently reinstate the unattributable relay for every + # future caller. Parent-side only -- it is not marshalled, on the same rule as ``_env`` below. + self._inbound = inbound self._config_dir = str(Path(config_dir)) - # Kept for the caller's signature (engine.py resolves and passes it), but NOT marshalled: the + # Kept for the caller's signature (``engine.py`` resolves it into the config source and + # ``wiring_runner._sandbox_for`` passes it here), but NOT marshalled: the # worker never read it — `load_config()` takes only a directory — and a dead field on the wire # is a field nobody validates. self._env = env @@ -416,6 +581,14 @@ def __init__( # after spawn, cleared by every ``_kill``. POSIX reaps via the worker's process group instead. self._job: int | None = None self._responses: queue.Queue[Any] = queue.Queue() + # The current generation's drain threads (frames on fd 1, stderr on fd 2), joined ONLY on the + # shutdown path -- see :meth:`close`. + self._threads: list[threading.Thread] = [] + # Monotonic per-session worker counter. Part of a relayed line's identity because a pid is NOT + # a unique generation id: an OS recycles pids (aggressively on Windows), and a stale relay can + # still be draining a killed child while the next one runs -- two generations' records would + # then be byte-indistinguishable, which is the attribution defect this change exists to fix. + self._generation = 0 self._lock = threading.Lock() self._closed = False @@ -435,6 +608,7 @@ def _spawn(self) -> None: # A fresh response queue per spawn so a prior (killed) worker's trailing EOF can't leak into # this generation's reads. self._responses = queue.Queue() + self._generation += 1 # Fixed argv (this interpreter + our own worker module), no shell, no # untrusted input in the command line — so B603 does not apply. ``start_new_session`` puts the # worker in its own POSIX process group so ``_kill`` can ``killpg`` its whole tree; it is a @@ -443,21 +617,49 @@ def _spawn(self) -> None: [sys.executable, "-m", WORKER_MODULE], stdin=subprocess.PIPE, stdout=subprocess.PIPE, - stderr=None, # let the child's stderr (logging) pass through to the engine's stderr + # CAPTURED, not inherited (BACKLOG #343, ADR 0166): with ``stderr=None`` the child's stderr + # WAS the engine's, so admin-authored Handler code wrote unframed, unattributed bytes -- + # including whole message bodies -- straight into the operator's log of record. + stderr=subprocess.PIPE, bufsize=0, close_fds=True, start_new_session=sys.platform != "win32", ) - assert proc.stdin is not None and proc.stdout is not None + assert proc.stdin is not None and proc.stdout is not None and proc.stderr is not None + # BOTH drains start before anything that can raise between here and the boot frame write. For + # fd 1 that ordering is pre-existing; for fd 2 it is a REQUIREMENT this change creates. A PIPE + # nobody drains blocks its writer once the fixed OS buffer fills (tens of KiB), and the boot frame + # below triggers ``load_config()`` -- top-level admin config, the earliest untrusted code and + # the first thing that can print. Undrained, every spawn would hang to ``startup_seconds`` and + # report a startup timeout naming the wrong cause. Starting them before the job assignment also + # closes the window in which that assignment raising would leave a live child with an undrained + # pipe and no reaper. Per-generation state travels as THREAD ARGUMENTS, never off ``self``, so + # a stale generation's drain cannot write into the live one's counters. + gen = self._generation + relay = _StderrRelay(self._inbound, proc.pid, gen) + self._threads = [ + threading.Thread( + target=self._reader_loop, + args=(proc.stdout, self._responses), + name=f"mf-sandbox-frames-{self._inbound}-{gen}", + daemon=True, + ), + threading.Thread( + target=relay.run, + args=(proc.stderr,), + name=f"mf-sandbox-stderr-{self._inbound}-{gen}", + daemon=True, + ), + ] + for thread in self._threads: + thread.start() # Assign the Windows kill-on-close job BEFORE the boot frame. The boot frame triggers # ``load_config()``, which runs top-level admin config — the earliest untrusted code and the # first chance to spawn a grandchild. Until then the worker parks on its first stdin read, so - # assigning here is race-free: any process the worker later spawns is already in the job. + # assigning here is race-free: any process the worker later spawns is already in the job. The + # drains above do not disturb that argument, which turns on the CHILD's first stdin read and + # not on what the parent's threads are doing. self._job = _assign_kill_on_close_job(proc) - reader = threading.Thread( - target=self._reader_loop, args=(proc.stdout, self._responses), daemon=True - ) - reader.start() try: _write_frame( proc.stdin, @@ -513,6 +715,13 @@ def _kill(self, proc: subprocess.Popen[bytes] | None) -> None: # response pipe) and would outlive a bare ``proc.kill()`` as an orphan still holding the pipe. # ``self._job`` is the current worker's kill-on-close job on Windows (``None`` on POSIX, where # the worker's process group is reaped instead). Clear it after — the handle is now closed. + # + # The same reap EOFs fd 2, so the stderr relay thread ends on its own here exactly as the frame + # reader does. Neither thread is joined on THIS path (a respawn must not wait on a grandchild + # that holds a pipe open, and this runs under the session lock), and neither pipe is closed: + # closing a file object under a mid-read thread raises ``ValueError``, which is not what either + # drain's ``except OSError`` catches, so it would escape into ``threading.excepthook``. The + # shutdown-only bounded join lives in :meth:`close`. _reap_process_tree(proc, self._job) self._job = None try: # noqa: SIM105 @@ -527,6 +736,18 @@ def close(self) -> None: with self._lock: self._closed = True self._kill(self._proc) + for thread in self._threads: + # A bounded join, and ONLY on the shutdown path. The stderr relay LOGS, and a daemon + # thread that logs can still be inside a handler's ``emit`` when ``logging.shutdown`` + # runs at exit -- writing to a closed stream, or holding a handler lock the atexit hook + # then blocks on. An UNBOUNDED join would be wrong (a surviving grandchild holds the + # pipes, and this runs under ``self._lock`` from ``asyncio.to_thread``), but a short one + # lets the final flush land before the handlers close. The reap above EOFs both pipes, + # so the usual cost is microseconds; the budget is spent only when a grandchild survived + # it, and the runner closes sessions SEQUENTIALLY, so that ceiling is per inbound. + # The respawn path in :meth:`_spawn` deliberately does not join at all. + thread.join(timeout=_STDERR_JOIN_SECONDS) + self._threads = [] def _reject_unsolicited(self, proc: subprocess.Popen[bytes] | None, when: str) -> None: """Drop the worker if anything is pending that no outstanding request asked for. @@ -535,8 +756,10 @@ def _reject_unsolicited(self, proc: subprocess.Popen[bytes] | None, when: str) - left over **after** its answer was written by something other than the call we made — a Handler writing straight to fd 1, or a grandchild that inherited it while the worker was alive. Letting such a frame sit in the queue is the whole exploit: the next dispatch would - take it as its own answer. It is not an authoring accident either — ``print()`` goes through - the text wrapper, not the frame writer — so there is no benign case to preserve. Drop the + take it as its own answer. It is not an authoring accident either — the child rebinds + ``sys.stdout`` to stderr at bootstrap (ADR 0166), so the text layer cannot reach fd 1 at all + and a frame arriving here was written by something that went looking for the raw descriptor. + There is no benign case to preserve. Drop the worker and dead-letter the message in hand; :meth:`_kill` then reaps that grandchild along with the rest of the worker's tree, so it cannot keep writing to the pipe. diff --git a/messagefoundry/pipeline/wiring_runner.py b/messagefoundry/pipeline/wiring_runner.py index cf9af681a..36a2481ca 100644 --- a/messagefoundry/pipeline/wiring_runner.py +++ b/messagefoundry/pipeline/wiring_runner.py @@ -2622,7 +2622,11 @@ def _sandbox_for(self, name: str) -> SandboxSession | None: # The engine's code-set tables travel once per spawn in the boot frame (not per dispatch), # so the child serves exactly what mode=off would rather than its own re-read of codesets/. session = SandboxSession( - policy, config_dir=cfg_dir, env=env, code_sets=self.registry.code_sets + policy, + inbound=name, # attributes the child's relayed stderr to this feed (ADR 0166) + config_dir=cfg_dir, + env=env, + code_sets=self.registry.code_sets, ) self._sandbox_sessions[name] = session return session diff --git a/tests/test_accepts_seam.py b/tests/test_accepts_seam.py index 72edc0724..05e4fb0e3 100644 --- a/tests/test_accepts_seam.py +++ b/tests/test_accepts_seam.py @@ -598,6 +598,7 @@ def test_accepts_runs_inside_the_sandbox_child(sandbox_graph: tuple[Registry, st session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -618,6 +619,7 @@ def test_pure_accepts_is_byte_identical_through_the_sandbox( session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) diff --git a/tests/test_phi_logging_inventory.py b/tests/test_phi_logging_inventory.py index 30ddbd8b3..4964935fc 100644 --- a/tests/test_phi_logging_inventory.py +++ b/tests/test_phi_logging_inventory.py @@ -673,11 +673,14 @@ def test_the_tray_file_sink_is_scoped_out_by_name() -> None: def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: """§7's filter-coverage claim must match how the ADR 0087 child actually configures logging. - The child inherits the engine's stderr (``stderr=None``) either way, so what decides the doc is - whether it builds its own **unfiltered** handler. It used to: a bare ``basicConfig``, whose handler - carries no filters, put WARNING+ records from admin-authored Handler code onto stream 1's own sink - outside the chain, and §7 disclosed that. It now calls ``configure_stderr_logging``, which installs - the same three filters (BACKLOG #1054), so the disclosure must be gone instead. + Two independent mechanisms cover the child's stderr, and §7 states both. In the CHILD: what decides + the doc is whether it builds its own **unfiltered** handler. It used to: a bare ``basicConfig``, + whose handler carries no filters, put WARNING+ records from admin-authored Handler code onto + stream 1's own sink outside the chain, and §7 disclosed that. It now calls + ``configure_stderr_logging``, which installs the same three filters (BACKLOG #1054), so the + disclosure must be gone instead. In the PARENT: the child's stderr is no longer *inherited* at all + (ADR 0166) — it is captured and relayed, with content gated below INFO — so §7's claim now rests on + that gate too, and the gate is pinned here rather than only described in prose. Pinned BOTH ways, because the interesting direction is the regression: a future edit that put ``basicConfig`` back would silently reopen the gap, and this reddens and demands §7 say so again. @@ -688,14 +691,23 @@ def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: encoding="utf-8" ) sandbox = (_ROOT / "messagefoundry" / "pipeline" / "sandbox.py").read_text(encoding="utf-8") - assert "stderr=None" in sandbox, "the child no longer inherits the engine's stderr; revisit §7" + assert "stderr=subprocess.PIPE" in sandbox, ( + "the child's stderr is no longer captured by the parent — it is inherited raw again, so §7's " + "'content only at DEBUG' gate does not exist. Revisit §7 and ADR 0166." + ) + assert "isEnabledFor(logging.DEBUG)" in sandbox, ( + "the stderr relay no longer gates content on DEBUG. §7 claims the never-log-bodies rule holds " + "BY CONSTRUCTION here; without this guard that claim rests on operator discipline instead." + ) unfiltered = "logging.basicConfig" in worker text = _doc_text() disclosed = "outside the filter chain" in text if unfiltered: assert disclosed, ( - "the sandbox worker child writes to the engine's INHERITED stderr through a bare " - "basicConfig, so §7's 'three filters on every record' claim is not true of it. Say so." + "the sandbox worker child emits through a bare basicConfig, whose handler carries no " + "filters, so §7's 'three filters on every record' claim is not true at the source. The " + "parent's ADR 0166 relay does not cover this: relayed records ride the engine's handlers, " + "but a record the CHILD writes unredacted is already unredacted on the wire. Say so." ) assert "in the engine process" in text, ( "the filter-coverage sentence must be scoped to the engine process" @@ -709,6 +721,11 @@ def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: "the child neither uses basicConfig nor configure_stderr_logging — it may have no filter " "chain at all. Establish which, and say so in §7." ) + assert "DEBUG" in _section_7(), ( + "§7 must name the level at which relayed child stderr content appears. Without it the " + "reader cannot act on the disclosure: they learn content is withheld and not where to " + "find it, nor that finding it puts full Handler output on a PHI-class log." + ) assert ServiceSettings().sandbox.mode == "off", ( "[sandbox].mode no longer defaults off; §7 describes an OPT-IN posture — revisit it here." ) diff --git a/tests/test_sandbox.py b/tests/test_sandbox.py index fb64f56aa..ad3f9d7db 100644 --- a/tests/test_sandbox.py +++ b/tests/test_sandbox.py @@ -12,12 +12,14 @@ from __future__ import annotations +import logging import math import os import queue import signal import sys import time +from collections.abc import Callable from pathlib import Path from types import MappingProxyType from typing import Any @@ -29,6 +31,7 @@ from messagefoundry.config.run_context import RunContext, run_contexts from messagefoundry.config.wiring import Registry, load_config from messagefoundry.pipeline import _sandbox_codec as codec +from messagefoundry.pipeline import sandbox as sandbox_mod from messagefoundry.pipeline._sandbox_codec import ( _Blobs, _Reader, @@ -43,6 +46,7 @@ SandboxMode, SandboxPolicy, SandboxSession, + _StderrRelay, ) from messagefoundry.store.store import MessageStore @@ -232,7 +236,9 @@ def _deliveries(registry: Registry, hname: str, **kw: object) -> list[tuple[str, def test_mode_off_session_is_byte_identical_and_never_spawns(graph: tuple[Registry, str]) -> None: registry, config_dir = graph ic = registry.inbound["IB_T"] - off = SandboxSession(SandboxPolicy(mode=SandboxMode.OFF), config_dir=config_dir, env=None) + off = SandboxSession( + SandboxPolicy(mode=SandboxMode.OFF), inbound="IB_T", config_dir=config_dir, env=None + ) # Router + Handler go through the OFF branch (in-process) — identical to sandbox=None. assert route_only(registry, ic, RAW, sandbox=off, run_context=RunContext()) == route_only( registry, ic, RAW @@ -253,6 +259,7 @@ def test_subprocess_parity_router_and_handler(graph: tuple[Registry, str]) -> No session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -272,6 +279,7 @@ def test_forbidden_import_is_denied_and_worker_survives(graph: tuple[Registry, s registry, config_dir = graph session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -294,6 +302,7 @@ def test_busy_loop_is_wall_capped_and_recovers(graph: tuple[Registry, str]) -> N registry, config_dir = graph session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=1.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -319,6 +328,7 @@ def test_db_lookup_in_sandbox_fails_closed(graph: tuple[Registry, str]) -> None: registry, config_dir = graph session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -336,6 +346,7 @@ def test_run_context_reaches_the_worker(graph: tuple[Registry, str]) -> None: registry, config_dir = graph session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -387,6 +398,7 @@ async def test_subprocess_marshals_live_store_run_context( assert isinstance(transform_rc.state_view, MappingProxyType) session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound="IB_T", config_dir=config_dir, env=None, ) @@ -435,9 +447,12 @@ def test_run_context_codec_snapshots_mappingproxy_views() -> None: # --- the IPC boundary itself (MFW2 codec) ------------------------------------- -def _session(config_dir: str, **kw: object) -> SandboxSession: +def _session(config_dir: str, inbound: str = "IB_T", **kw: object) -> SandboxSession: + # The default lives in this TEST helper only, never in the production constructor, where a default + # would silently reinstate the unattributable relay ADR 0166 exists to close. return SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), + inbound=inbound, config_dir=config_dir, env=None, **kw, # type: ignore[arg-type] @@ -1095,3 +1110,377 @@ def test_worker_kill_reaps_the_whole_process_tree(tmp_path: Path) -> None: if grandchild_pid is not None: _best_effort_kill_pid(grandchild_pid) session.close() + + +# --- (e) child stderr is captured and relayed, content confined below INFO ----- +# BACKLOG #343 / ADR 0166. Two problems share one root: (a) a sandboxed Handler's line was +# byte-indistinguishable from an engine line, and (b) a Handler that printed a message body wrote a +# full payload into the general log. (b) is the one CLAUDE.md section 9 forbids, and the tests below +# pin the property that closes it BY CONSTRUCTION: no call site above DEBUG carries child content. + +_STDERR_GRAPH = """ +import sys + +from messagefoundry import inbound, outbound, router, handler, MLLP, Send + +inbound("IB_ERR", MLLP(port=19341), router="r_err") +outbound("OB_ERR", MLLP(host="127.0.0.1", port=19342)) + + +@router("r_err") +def r_err(msg): + return "h_body" + + +@handler("h_body") +def h_body(msg): + # ADR 0166 (b): a Handler writing a full message body to stderr. Synthetic HL7 only. + print(str(msg), file=sys.stderr) + return Send("OB_ERR", "OK") + + +@handler("h_ctrl") +def h_ctrl(msg): + # A CR and an ANSI escape. Both must be neutralised, or one child write is not one log record. + sys.stderr.write("MEFOR_RELAY_MARKER\\x1b[31m\\rtail\\n") + sys.stderr.flush() + return Send("OB_ERR", "OK") + + +@handler("h_raw_stdout") +def h_raw_stdout(msg): + # A RAW write past the text layer the bootstrap rebind moves. WITH the rebind sys.stdout IS + # stderr, so this lands on fd 2 and the dispatch is unaffected. WITHOUT it, a COMPLETE forged + # frame reaches fd 1 ahead of the real answer and the parent decodes it as this dispatch's reply. + sys.stdout.buffer.write(b"\\x00\\x00\\x00\\x07garbage") + sys.stdout.buffer.flush() + return Send("OB_ERR", "OK") +""" + +#: Writes 1 MiB to stderr at MODULE scope, i.e. inside ``load_config()`` -- before the child can write +#: its boot reply. This is the deadlock ADR 0166 says the decision CREATES: a PIPE nobody drains blocks +#: its writer once the OS buffer fills (order 64 KiB). +_FLOOD_GRAPH = """ +import sys + +from messagefoundry import inbound, outbound, router, handler, MLLP, Send + +sys.stderr.write("x" * (1024 * 1024) + "\\n") +sys.stderr.flush() + +inbound("IB_FLOOD", MLLP(port=19343), router="r_flood") +outbound("OB_FLOOD", MLLP(host="127.0.0.1", port=19344)) + + +@router("r_flood") +def r_flood(msg): + return "h_flood_ok" + + +@handler("h_flood_ok") +def h_flood_ok(msg): + return Send("OB_FLOOD", "OK") +""" + + +def _stderr_graph(tmp_path: Path) -> tuple[Registry, str]: + (tmp_path / "graph.py").write_text(_STDERR_GRAPH, encoding="utf-8") + return load_config(tmp_path), str(tmp_path) + + +def _notices(caplog: pytest.LogCaptureFixture) -> list[logging.LogRecord]: + """The relay's attributed count records -- identity and counts, never content.""" + return [ + r + for r in list(caplog.records) + if r.levelno == logging.WARNING and "wrote to stderr" in r.getMessage() + ] + + +def _content_records(caplog: pytest.LogCaptureFixture) -> list[logging.LogRecord]: + return [r for r in list(caplog.records) if r.getMessage().startswith("sandbox stderr [")] + + +def _await(predicate: Callable[[], bool], timeout: float = 10.0) -> bool: + """Poll ``predicate`` to a deadline. The relay is a THREAD, so a record it emits is not ordered + against the dispatch that provoked it; and polling inside the test body keeps the assertion clear + of conftest's teardown quiescing of the ``messagefoundry`` logger.""" + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + if predicate(): + return True + time.sleep(0.05) + return False + + +def test_at_info_a_printed_message_body_never_reaches_a_log_record( + tmp_path: Path, caplog: pytest.LogCaptureFixture +) -> None: + """THE section 9 property, end to end through a real spawned worker. + + A Handler prints the whole message to stderr. At INFO the operator must learn THAT the inbound's + Handler wrote to stderr -- attributed, with a count -- and must not receive one byte of the body. + + FALSIFICATION, and it is worth recording precisely because it took two edits rather than one: the + property is held by two INDEPENDENT mechanisms, and breaking either alone leaves it standing. + Deleting the ``log.isEnabledFor(logging.DEBUG)`` guard changes nothing while the only content call + site is ``log.debug``; raising that call site to ``log.info`` changes nothing while the guard + stands. Break BOTH and this goes red with ``DOE^JANE`` in a record at INFO (measured).""" + registry, config_dir = _stderr_graph(tmp_path) + caplog.set_level(logging.INFO) + session = _session(config_dir, inbound="IB_ERR") + try: + assert _deliveries(registry, "h_body", sandbox=session, run_context=RunContext()) == [ + ("OB_ERR", "OK") + ] + assert _await(lambda: bool(_notices(caplog))), "no attributed stderr notice was emitted" + finally: + session.close() + + notice = _notices(caplog)[0] + assert "IB_ERR" in notice.getMessage(), "the notice does not attribute the line to its inbound" + assert not _content_records(caplog), "child stderr CONTENT was relayed at INFO" + joined = "\n".join(r.getMessage() for r in caplog.records) + for token in ("DOE", "JANE", "900001", "ADT^A01"): + assert token not in joined, f"{token!r} from a printed message body reached a log at INFO" + + +def test_at_debug_content_is_relayed_attributed_and_control_scrubbed( + tmp_path: Path, caplog: pytest.LogCaptureFixture +) -> None: + """The diagnosability half: at DEBUG the operator does get the content, attributed to the inbound, + the child pid and the worker generation, with control bytes neutralised so one child write cannot + become two log lines or drive a terminal. + + ``caplog``'s handler carries NO filters, so what this measures is the relay's OWN scrub -- which is + the point: that scrub is the relay's framing contract and must not depend on how the host process + configured logging. Redaction is deliberately NOT asserted here; it is a property of the engine's + handlers, which ``caplog`` does not install. + + FALSIFICATION: remove the ``scrub_control_chars`` call in ``_StderrRelay._line`` and the raw ESC/CR + assertions below fail.""" + registry, config_dir = _stderr_graph(tmp_path) + caplog.set_level(logging.DEBUG) + session = _session(config_dir, inbound="IB_ERR") + try: + assert _deliveries(registry, "h_ctrl", sandbox=session, run_context=RunContext()) == [ + ("OB_ERR", "OK") + ] + assert _await( + lambda: any("MEFOR_RELAY_MARKER" in r.getMessage() for r in _content_records(caplog)) + ), "the child's stderr line was not relayed at DEBUG" + finally: + session.close() + + line = next(r for r in _content_records(caplog) if "MEFOR_RELAY_MARKER" in r.getMessage()) + message = line.getMessage() + assert "IB_ERR" in message and "pid " in message and "gen " in message, message + assert "\x1b" not in message and "\r" not in message, "a raw control byte survived the relay" + assert "\\x1b" in message and "\\r" in message, "the control bytes were dropped, not escaped" + assert "tail" in message, "the text after the CR was lost instead of being kept on one record" + + +def test_a_raw_write_to_fd_1_cannot_forge_a_frame_because_stdout_is_rebound( + tmp_path: Path, +) -> None: + """ADR 0166 D3, the adjacent defect closed with the same fd discipline. + + The Handler writes a COMPLETE forged frame through ``sys.stdout.buffer``. With the bootstrap rebind + ``sys.stdout`` is stderr, so those bytes go to fd 2 and the dispatch answers normally. Without it + they reach fd 1 ahead of the real reply and the parent decodes garbage as this dispatch's answer -- + deterministic, unlike a bare ``print()``, whose survival today is the buffering luck the item names. + + FALSIFICATION: delete the ``_redirect_stdout_to_stderr()`` call in ``_sandbox_worker.main`` and this + raises ``SandboxError`` instead of delivering.""" + registry, config_dir = _stderr_graph(tmp_path) + session = _session(config_dir, inbound="IB_ERR") + try: + assert _deliveries(registry, "h_raw_stdout", sandbox=session, run_context=RunContext()) == [ + ("OB_ERR", "OK") + ] + finally: + session.close() + + +def test_a_bootstrap_stderr_flood_does_not_wedge_the_spawn(tmp_path: Path) -> None: + """The deadlock this change CREATES, and the ordering that closes it. + + Config module scope writes 1 MiB to stderr, so the flood happens inside ``load_config()`` -- before + the boot reply. ``startup_seconds`` is deliberately short so a regression fails fast instead of + eating the 60s pytest-timeout budget. + + FALSIFICATION: move the drain-thread start below the boot-frame write in ``_spawn`` and this hangs + to ``startup_seconds`` and raises ``SandboxError``.""" + (tmp_path / "graph.py").write_text(_FLOOD_GRAPH, encoding="utf-8") + session = SandboxSession( + SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0, startup_seconds=10.0), + inbound="IB_FLOOD", + config_dir=str(tmp_path), + env=None, + ) + try: + started = time.monotonic() + session._spawn() # the whole bootstrap: boot frame -> load_config() -> ready reply + assert time.monotonic() - started < 10.0 + assert session._proc is not None + finally: + session.close() + + +def test_the_relay_thread_ends_when_the_worker_tree_is_reaped(tmp_path: Path) -> None: + """A second drain thread is a second teardown obligation (ADR 0166), and it is EOF-driven. + + Reuses the orphan graph so a GRANDCHILD also holds fd 2 -- which is the case the EOF argument + actually rests on, since the immediate worker dying is not enough to close a pipe another process + still holds. Nothing signals the thread and nothing closes the pipe: the tree reap EOFs fd 2 and the + drain returns. + + FALSIFICATION: force ``_assign_kill_on_close_job`` to return ``None`` (the BACKLOG #342 + falsification) and the grandchild survives, fd 2 never EOFs, and this thread stays alive.""" + registry, config_dir, pidfile = _orphan_graph(tmp_path) + session = _session(config_dir, inbound="IB_ORPH") + grandchild_pid: int | None = None + try: + assert _deliveries(registry, "h_orphan", sandbox=session, run_context=RunContext()) == [ + ("OB_O", "SPAWNED") + ] + grandchild_pid = int(pidfile.read_text()) + relay = next(t for t in session._threads if t.name.startswith("mf-sandbox-stderr-")) + assert relay.name == "mf-sandbox-stderr-IB_ORPH-1", relay.name + assert relay.is_alive() + + session._kill(session._proc) + assert _await(lambda: not relay.is_alive()), ( + "the stderr relay thread outlived the worker tree reap -- fd 2 never reached EOF" + ) + finally: + if grandchild_pid is not None: + _best_effort_kill_pid(grandchild_pid) + session.close() + + +def test_notices_carry_a_generation_so_a_recycled_pid_cannot_confuse_two_workers( + tmp_path: Path, caplog: pytest.LogCaptureFixture +) -> None: + """Attribution is per worker GENERATION, not per pid. + + A stale generation's relay can still be draining a killed child while the live one runs, and an OS + recycles pids -- so ``(inbound, pid)`` alone can make two generations' records byte-identical, which + is the very defect this change exists to fix. Also pins that the second generation's counters start + clean rather than inheriting the first's. + + FALSIFICATION: hoist the relay's counters onto the session and generation 2's running total is + inflated by generation 1's lines.""" + registry, config_dir = _stderr_graph(tmp_path) + caplog.set_level(logging.INFO) + session = _session(config_dir, inbound="IB_ERR") + try: + _deliveries(registry, "h_ctrl", sandbox=session, run_context=RunContext()) + assert _await(lambda: len(_notices(caplog)) >= 1) + session._kill(session._proc) # forces a fresh generation on the next dispatch + _deliveries(registry, "h_ctrl", sandbox=session, run_context=RunContext()) + assert _await(lambda: len(_notices(caplog)) >= 2) + finally: + session.close() + + generations = [_arg(r, 2) for r in _notices(caplog)] + assert generations[:2] == [1, 2], generations + second = next(r for r in _notices(caplog) if _arg(r, 2) == 2) + assert _arg(second, 4) == 1, ( + "generation 2's running total inherited generation 1's lines -- the counters are shared" + ) + + +# --- the relay in isolation (no spawn) ---------------------------------------- + + +def _arg(record: logging.LogRecord, index: int) -> int: + """One positional ``%``-arg off a relay record, as an int. The notice reports identity and counts + as discrete args precisely so a test can read them without parsing prose.""" + assert isinstance(record.args, tuple) + value = record.args[index] + assert isinstance(value, int) + return value + + +def _relay() -> _StderrRelay: + return _StderrRelay("IB_U", 4242, 7) + + +def test_the_notice_is_rate_limited_and_reports_every_suppressed_line( + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture +) -> None: + """The notice is what an operator at INFO gets INSTEAD of content, so it must not become the flood + it reports -- and a throttled line must be COUNTED, never silently dropped (the count-and-log + invariant applied to the relay's own records). + + FALSIFICATION: remove the window check in ``_notice`` and 500 lines produce 500 notices.""" + monkeypatch.setattr(sandbox_mod, "_STDERR_NOTICE_SECONDS", 3600.0) + caplog.set_level(logging.INFO) + relay = _relay() + relay.feed(b"line\n" * 500) + relay.close() + + notices = _notices(caplog) + assert 1 <= len(notices) <= 2, f"{len(notices)} notices for one throttle window" + counted = sum(_arg(r, 3) for r in notices) + assert counted == 500, f"{counted} lines reported, 500 written -- suppressed lines were dropped" + + +def test_the_line_cap_bounds_a_record_without_discarding_a_byte( + caplog: pytest.LogCaptureFixture, +) -> None: + """The cap is a MEMORY bound on the parent, never a redaction -- which is what distinguishes it + from the per-line byte cap ADR 0166 rejected. Reaching it splits one write across several records + and discards nothing. (The rejected cap would have kept MSH and PID and thrown the rest away: the + worst available redaction for an HL7 v2 payload, since that is precisely the identifying part.)""" + caplog.set_level(logging.DEBUG) + cap = sandbox_mod._STDERR_LINE_CAP + relay = _relay() + relay.feed(b"X" * (3 * cap)) + relay.close() + + records = _content_records(caplog) + assert records, "nothing was relayed at DEBUG" + for record in records: + assert isinstance(record.args, tuple) + text = record.args[3] + assert isinstance(text, str) and len(text) <= cap + total = sum(r.getMessage().count("X") for r in records) + assert total == 3 * cap, f"{total} bytes relayed of {3 * cap} written -- the cap DISCARDED" + + # A terminator landing exactly ON the bound is a complete cap-length line, not an over-length run: + # one record, and no spurious empty one behind it. + caplog.clear() + boundary = _relay() + boundary.feed(b"Y" * cap + b"\n") + boundary.close() + exact = _content_records(caplog) + assert len(exact) == 1, [r.getMessage()[:60] for r in exact] + assert exact[0].getMessage().count("Y") == cap + + +def test_the_relay_survives_hostile_bytes_and_a_dead_pipe( + caplog: pytest.LogCaptureFixture, +) -> None: + """The relay is the sole drainer, so it must never raise out of ``run()``: an escaping exception + ends the drain, and an undrained pipe blocks the child. Covers a multi-byte character split across + two reads, invalid UTF-8, an embedded NUL, and an ``OSError`` mid-read.""" + caplog.set_level(logging.DEBUG) + relay = _relay() + relay.feed(b"caf\xc3") # a UTF-8 sequence split across the read boundary + relay.feed(b"\xa9\n") + relay.feed(b"\xff\xfe bad utf-8\n") + relay.feed(b"nul\x00here\n") + relay.close() + + joined = "\n".join(r.getMessage() for r in _content_records(caplog)) + assert "café" in joined, "a character split across two reads was corrupted" + assert "bad utf-8" in joined # decoded with replacement rather than raising + assert "\x00" not in joined and "\\x00" in joined, "a raw NUL survived the relay" + + class _Exploding: + def read(self, _n: int) -> bytes: + raise OSError("pipe died with the worker") + + _StderrRelay("IB_U", 1, 1).run(_Exploding()) # type: ignore[arg-type] diff --git a/tests/test_sandbox_worker_logging.py b/tests/test_sandbox_worker_logging.py index 41281c5cb..af8683f30 100644 --- a/tests/test_sandbox_worker_logging.py +++ b/tests/test_sandbox_worker_logging.py @@ -12,8 +12,10 @@ from __future__ import annotations +import ast import subprocess import sys +from pathlib import Path #: Synthetic HL7 (never real PHI). HL7-shaped so ``redact`` rewrites the span. SYNTHETIC_PHI = "PID|1||100^^^H^MR||DOE^JANE^Q||19800101|F" @@ -53,3 +55,57 @@ def test_sandbox_worker_child_logs_redacted_and_scrubbed_to_stderr() -> None: assert "\\r\\n" in err assert "forged-record" in err # kept and diagnosable, just not at column 0 assert len([line for line in err.splitlines() if line.strip()]) == 1 + + +def test_the_stdout_rebind_sits_between_the_frame_capture_and_the_boot_read() -> None: + """ADR 0166 D3 is a SOURCE-ORDER property, so it needs a source-order instrument (SDS-3.8). + + ``_redirect_stdout_to_stderr()`` must run AFTER ``main`` captures ``sys.stdout.buffer`` -- at module + scope that capture would resolve to fd 2 and every MFW2 frame would go to the wrong pipe -- and + BEFORE the boot frame is read, whose reply path runs ``load_config()``, the earliest untrusted code + and the first thing that can print. + + No runtime test can see this: moving the rebind to module scope breaks every frame, and moving it + after the boot read leaves a window open, yet the test above passes either way because it never + spawns a worker. The instrument has to be the source itself. + + Measured on the AST and not on the text, because a text scan matches a COMMENT naming the call — + which is exactly how the first draft of this test passed while the call was deleted.""" + source = ( + Path(__file__).resolve().parents[1] / "messagefoundry" / "pipeline" / "_sandbox_worker.py" + ).read_text(encoding="utf-8") + main = next( + node + for node in ast.walk(ast.parse(source)) + if isinstance(node, ast.FunctionDef) and node.name == "main" + ) + nodes = list(ast.walk(main)) + + def _call_line(name: str) -> int: + lines = [ + n.lineno + for n in nodes + if isinstance(n, ast.Call) and isinstance(n.func, ast.Name) and n.func.id == name + ] + assert lines, f"main() contains no call to {name}()" + return min(lines) + + capture = min( + ( + n.lineno + for n in nodes + if isinstance(n, ast.Attribute) + and n.attr == "buffer" + and isinstance(n.value, ast.Attribute) + and n.value.attr == "stdout" + ), + default=-1, + ) + assert capture > 0, "main() no longer captures sys.stdout.buffer as the raw frame handle" + rebind = _call_line("_redirect_stdout_to_stderr") + boot_read = _call_line("_read_frame_bytes") + assert capture < rebind < boot_read, ( + "the fd-1 capture / stdout rebind / boot-frame read are out of order in main(): the rebind " + f"must follow the capture and precede the first untrusted code, ADR 0166 D3 " + f"(capture line {capture}, rebind {rebind}, boot read {boot_read})" + ) From 5d9133114a49be841c52b9bcd21e720b5893dd1f Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 19:07:27 -0500 Subject: [PATCH 05/16] fix(sandbox): two confirmed findings from the #343 adversarial review (BACKLOG #343) Both were found by the review round AFTER the implementation was committed, and both are claims rather than behaviour -- which is exactly the class that survives a green suite. F1. _reject_unsolicited's docstring asserted that the ADR 0166 stdout rebind means "the text layer cannot reach fd 1 at all", so "there is no benign case to preserve". BOTH FALSE, and this docstring is where a DESTRUCTIVE action is reasoned from -- drop the worker and dead-letter the message in hand. Rebinding the NAME sys.stdout leaves the descriptor open: sys.__stdout__ is still a text layer on fd 1, its .buffer IS the BufferedWriter the worker captured as the frame writer, and os.write(1, ...) and open(1, "wb") reach it too. The reviewer measured a benign one-liner that destroys the worker. THE SAME COMMIT ALREADY REFUSED THIS CLAIM TWICE -- in _sandbox_worker.py's bootstrap comment and in ADR 0166, both citing SDS-3.7 -- so the change contradicted itself and the false half was the one driving the destructive path. That is the compensating-control-on-a-false-premise shape, reintroduced one file away from where it had just been rejected. THE ACTION IS UNCHANGED AND NEVER NEEDED THE STRONGER CLAIM. A frame no outstanding request asked for violates the one-request-one-frame protocol whether it was written deliberately or by accident, and the queue cannot tell the difference: benign-but-unsolicited is still a frame the next dispatch would misread as its answer. The justification is now the protocol violation, not an impossibility. F2. The drain-ordering test's FALSIFICATION instruction was measurably wrong. It said to move the drain start below the boot-frame WRITE; ADR 0166 records the measurement that this does NOT wedge, because the parent then blocks on the reply while the drain is already running. It wedges when the drain starts below the point the boot REPLY is read. Corrected, with the reason kept: a falsification that does not falsify is worse than none, because it reads as a checked escape hatch and the one person who follows it concludes the guard is untestable rather than that the instruction was wrong. The PHI hunt found no section 9 violation, and found it by measurement rather than reading: the relay was driven through the real configure_logging() filter chain -- not caplog, which carries no filters -- at INFO, WARNING and DEBUG with a full synthetic HL7 body plus an over-cap terminator-free run. At INFO/WARNING: two records, both the counts-only notice, and none of the synthetic identifiers in either the records or the rendered stream. Verified: ruff check and format clean, mypy strict clean over 266 source files, tests/test_sandbox.py 34 passed. --- messagefoundry/pipeline/sandbox.py | 22 ++++++++++++++++++---- tests/test_sandbox.py | 10 ++++++++-- 2 files changed, 26 insertions(+), 6 deletions(-) diff --git a/messagefoundry/pipeline/sandbox.py b/messagefoundry/pipeline/sandbox.py index f8d78c54f..0ddd83c08 100644 --- a/messagefoundry/pipeline/sandbox.py +++ b/messagefoundry/pipeline/sandbox.py @@ -756,13 +756,27 @@ def _reject_unsolicited(self, proc: subprocess.Popen[bytes] | None, when: str) - left over **after** its answer was written by something other than the call we made — a Handler writing straight to fd 1, or a grandchild that inherited it while the worker was alive. Letting such a frame sit in the queue is the whole exploit: the next dispatch would - take it as its own answer. It is not an authoring accident either — the child rebinds - ``sys.stdout`` to stderr at bootstrap (ADR 0166), so the text layer cannot reach fd 1 at all - and a frame arriving here was written by something that went looking for the raw descriptor. - There is no benign case to preserve. Drop the + take it as its own answer. Drop the worker and dead-letter the message in hand; :meth:`_kill` then reaps that grandchild along with the rest of the worker's tree, so it cannot keep writing to the pipe. + **The justification is the protocol violation, NOT a claim that fd 1 is unreachable.** An + earlier version of this docstring said the ADR 0166 stdout rebind meant "the text layer cannot + reach fd 1 at all", so "there is no benign case to preserve". **Both were false, and this + docstring is where a DESTRUCTIVE action is reasoned from, which is what made it worth + correcting rather than softening.** Rebinding the *name* ``sys.stdout`` leaves the descriptor + wide open: ``sys.__stdout__`` is still a text layer on fd 1 — its ``.buffer`` is the very + ``BufferedWriter`` :func:`_sandbox_worker.main` captured as the frame writer — and + ``os.write(1, ...)`` and ``open(1, "wb")`` reach it too. What the rebind actually removes is + the *accidental* case (a bare ``print()`` in a Handler), which is worth having and is all it + claims in ADR 0166 and in the worker's own bootstrap comment; asserting more here contradicted + both, in the same change that wrote them. + + The action is unchanged and does not need the stronger claim: a frame no outstanding request + asked for violates the one-request-one-frame protocol whether it was written deliberately or + by accident, and the queue cannot tell the difference. Benign-but-unsolicited is still a frame + the next dispatch would misread as its answer. + :data:`_EOF` is the opposite case and must NOT be treated the same way. It is a parent-private singleton with no wire form (see :class:`_Eof`), so a worker cannot manufacture one — it carries no trust information at all, only "the peer is gone". Dead-lettering on it would fail diff --git a/tests/test_sandbox.py b/tests/test_sandbox.py index ad3f9d7db..e1173f94f 100644 --- a/tests/test_sandbox.py +++ b/tests/test_sandbox.py @@ -1309,8 +1309,14 @@ def test_a_bootstrap_stderr_flood_does_not_wedge_the_spawn(tmp_path: Path) -> No the boot reply. ``startup_seconds`` is deliberately short so a regression fails fast instead of eating the 60s pytest-timeout budget. - FALSIFICATION: move the drain-thread start below the boot-frame write in ``_spawn`` and this hangs - to ``startup_seconds`` and raises ``SandboxError``.""" + FALSIFICATION: move the drain-thread start below the point where the boot **reply** is read in + ``_spawn`` and this hangs to ``startup_seconds`` and raises ``SandboxError``. + + NOT below the boot-frame WRITE, which is what this said first and is measurably wrong: starting + the drain immediately after the write does NOT wedge, because the parent then blocks on the reply + while the drain is already running (ADR 0166 records the measurement). A falsification that does + not falsify is worse than none -- it reads as a checked escape hatch, and the one person who + follows it concludes the guard is untestable rather than that the instruction was wrong.""" (tmp_path / "graph.py").write_text(_FLOOD_GRAPH, encoding="utf-8") session = SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0, startup_seconds=10.0), From a956293e8530c2e19c0c92cf24ae9ff2962872ae Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 19:35:40 -0500 Subject: [PATCH 06/16] feat(store): monotonic-prefix audit comparator beside the exact seal, SQLite (BACKLOG #328) audit-verify cannot detect a truncated tail. The startup auto-verify is a BARE WALK -- it confirms the chain it can see is internally consistent and has nothing to compare that chain's LENGTH against, so removing the tail leaves a shorter, perfectly valid chain and nothing objects. THE STORED ANCHOR COULD NOT BE WIRED THERE, and that is why this was a design fork rather than a fill-in. expected_anchor is an EXACT point-in-time seal: it requires the CURRENT head to equal the recorded one, so any appended row diverges. A running instance writes audit rows, so consuming a stored anchor at startup would alarm on essentially every restart. That property is DESIGNED and pinned by test_an_anchor_goes_stale_on_the_next_appended_row; this adds a SECOND comparator beside it and does not weaken that test, which still passes unmodified. expected_prefix asks the weaker, useful question: was the recorded state ever true, and has the chain only GROWN since? It holds the head captured AT the recorded position against the recorded one. CHOSEN OVER SEAL-ON-STOP / CHECK-ON-START BECAUSE THAT IS BLIND EXACTLY WHERE THE THREAT LIVES. Sealing during a clean shutdown detects truncation across a clean stop, and a tamperer does not shut down cleanly. A control that needs the adversary's cooperation to arm itself is a ceremony, not a control. Prefix-assertion is also strictly stronger than the item asked for: it catches a mid-chain rewrite too. WRITTEN ONCE AND EXPORTED rather than stated per backend -- audit_prefix_verdict lives beside audit_row_hash / audit_mac_bytes, which postgres.py and sqlserver.py already import. A predicate restated per backend is the copy-versus-single-source defect BACKLOG #1253 catalogues, where a later hardening reaches one copy and silently misses the rest. THE CAPTURE IS A POSITION TEST, NOT A DATA-DEPENDENT BRANCH, so it does not reintroduce the early return the walk deliberately avoids (ASVS 11.2.4, stated in the walk's own comments). A prefix_head of None means the walk never reached the recorded position -- the truncation case -- and must FAIL rather than pass vacuously. THE NEGATIVE CONTROL CAUGHT A VACUOUS TEST OF MY OWN AND THE FIRST VERSION IS RECORDED IN THE TEST. Deleting the head compare left the suite GREEN. The rewrite-a-row-in-place construction breaks the hash chain, so the WALK reports "chain broken" and returns before the comparator is consulted -- the test passed for a reason unrelated to what it claimed. Rebuilt as a SAME-COUNT TAIL REPLACEMENT (truncate behind the engine's back, then let the engine append replacements through its own API, so the chain is internally valid and the count is restored); only the head at the anchored position distinguishes it. With that shape, deleting the head compare reds exactly that test and no other. SQLite only in this commit. Postgres and SQL Server share the primitive but NOT the loop: both SQLite and Postgres carry a running `count`, while SQL SERVER USES len(rows) AND TRACKS NO POSITION, so its capture needs a counter the other two already have. Wiring those two plus the Store protocol is the next layer, deliberately not folded in here. Verified: mypy strict clean over 266 source files, ruff check and format clean, tests/test_audit_integrity.py 48 passed, mutation-proved in both directions with the plant asserted before the run. --- messagefoundry/store/store.py | 65 +++++++++++++++++++- tests/test_audit_integrity.py | 111 ++++++++++++++++++++++++++++++++++ 2 files changed, 175 insertions(+), 1 deletion(-) diff --git a/messagefoundry/store/store.py b/messagefoundry/store/store.py index f96581a94..4d63dbd3f 100644 --- a/messagefoundry/store/store.py +++ b/messagefoundry/store/store.py @@ -974,6 +974,54 @@ def audit_row_hash( return hmac.new(key, data, hashlib.sha256).hexdigest() +def audit_prefix_verdict( + expected_prefix: tuple[int, str], prefix_head: str | None, count: int +) -> tuple[bool, str | None]: + """Is the recorded anchor a PREFIX of the chain as it stands now? (BACKLOG #328) + + THE SECOND COMPARATOR, BESIDE THE EXACT ONE -- NOT A REPLACEMENT. ``expected_anchor`` is an exact + point-in-time seal: it requires the chain's CURRENT head to equal the recorded one, so any appended + row makes it diverge. That is a DESIGNED property, pinned by + ``test_an_anchor_goes_stale_on_the_next_appended_row``, and it is why the startup auto-verify could + never consume a stored anchor -- a running instance writes audit rows, so it would alarm on + essentially every restart. + + This asks the weaker and more useful question: *was the recorded state ever true, and has the chain + only GROWN since?* It holds the head captured AT row ``expected_prefix[0]`` against the recorded + one. Rows appended afterwards are irrelevant to it, so it survives restarts -- while still catching + the two things #328 is about: a TRUNCATED tail (fewer rows than recorded) and a MID-CHAIN REWRITE + (the head at that position no longer matches). + + **Chosen over seal-on-stop/check-on-start because that alternative is blind exactly where the + threat lives.** Sealing during a clean shutdown detects truncation across a clean stop -- and a + tamperer does not shut down cleanly. A control that needs the adversary's cooperation to arm itself + is a ceremony, not a control. + + ``prefix_head`` is ``None`` when the walk never reached that position, which IS the truncation case + and must fail rather than pass vacuously -- a missing capture is the strongest evidence the + comparator can see, not an absence of evidence. + + Written ONCE and imported by the other backends deliberately: this predicate stated per-backend is + the copy-versus-single-source defect BACKLOG #1253 catalogues, where a later hardening reaches one + copy and silently misses the rest. + """ + exp_count, exp_head = expected_prefix + # Bind the compare FIRST so it is always evaluated, matching the exact comparator's idiom: the + # anchor head is a MAC, so it gets constant-time treatment and the work does not vary with where + # the mismatch is (ASVS 11.2.4 -- the walk above is written the same way, and for the same reason). + head_ok = prefix_head is not None and hmac.compare_digest( + audit_mac_bytes(prefix_head), audit_mac_bytes(exp_head) + ) + if count < exp_count or not head_ok: + have = "(never reached)" if prefix_head is None else f"{prefix_head[:12]!r}" + return ( + False, + f"audit log is not an extension of the recorded prefix (have {count} row(s), head at " + f"row {exp_count} {have}, expected {exp_head[:12]!r}) — truncated or rewritten", + ) + return True, None + + def audit_mac_bytes(value: str | None) -> bytes: """Normalise a stored/recomputed ``audit_log.row_hash`` to comparison bytes for :func:`hmac.compare_digest` (ASVS 11.2.4). Shared verbatim by all three store backends so the @@ -7717,7 +7765,10 @@ async def audit_anchor(self) -> tuple[int, str]: return int(row["n"]), (row["head"] or "") async def verify_audit_chain( - self, *, expected_anchor: tuple[int, str] | None = None + self, + *, + expected_anchor: tuple[int, str] | None = None, + expected_prefix: tuple[int, str] | None = None, ) -> tuple[bool, str | None]: """Recompute the audit hash-chain in order; returns ``(ok, message)``. @@ -7754,6 +7805,9 @@ async def verify_audit_chain( prev = "" count = 0 first_break: int | None = None + #: Head as it stood AT ``expected_prefix[0]`` rows. Stays None when the walk never gets there, + #: which is the truncation case and must FAIL rather than pass vacuously (BACKLOG #328). + prefix_head: str | None = None for r in rows: # Per-row secret: keyless below the #190 watermark, keyed at/above it (in-heap HMAC key OR # isolated-module Transit MAC) — so a keyless prefix and a keyed suffix both verify across an @@ -7785,6 +7839,11 @@ async def verify_audit_chain( # row, instead of cascading a false break onto every successor. prev = r["row_hash"] or "" count += 1 + # BACKLOG #328: remember the head AT the recorded prefix position, in this same pass. A + # POSITION test, not a data-dependent branch, so it does not reintroduce the early-return + # the walk deliberately avoids (ASVS 11.2.4) and costs one comparison per row. + if expected_prefix is not None and count == expected_prefix[0]: + prefix_head = prev if first_break is not None: return False, f"audit chain broken at row id={first_break}" if expected_anchor is not None: @@ -7799,6 +7858,10 @@ async def verify_audit_chain( f"audit log diverges from recorded anchor (have {count} row(s) head {prev[:12]!r}, " f"expected {exp_count} head {exp_head[:12]!r}) — truncated or rewritten", ) + if expected_prefix is not None: + ok, msg = audit_prefix_verdict(expected_prefix, prefix_head, count) + if not ok: + return False, msg return True, f"verified {count} audit row(s)" async def has_prior_backup_history(self) -> bool: diff --git a/tests/test_audit_integrity.py b/tests/test_audit_integrity.py index 14a66e665..5cdc0fc55 100644 --- a/tests/test_audit_integrity.py +++ b/tests/test_audit_integrity.py @@ -10,6 +10,7 @@ import hmac import json import re +import sqlite3 from pathlib import Path import pytest @@ -898,3 +899,113 @@ async def test_migration_adds_client_to_a_preexisting_store(tmp_path: Path) -> N assert "4" in (message or "") finally: await store.close() + + +# --------------------------------------------------------------------------- BACKLOG #328 +# The monotonic-prefix comparator, which sits BESIDE the exact seal above rather than replacing it. +# The test directly above this block pins the exact seal's staleness as DESIGNED; nothing here may +# loosen it, and the first test asserts BOTH comparators on one chain so the pair cannot drift apart. + + +def test_a_prefix_anchor_survives_an_append_where_the_exact_anchor_must_not(tmp_path: Path) -> None: + """The whole reason #328 exists, asserted as a CONTRAST rather than in isolation. + + A running instance writes audit rows, so an exact anchor consumed by the startup auto-verify would + alarm on essentially every restart -- that is why the anchor could never be wired there. The prefix + comparator asks the weaker question (*was the recorded state ever true, and has the chain only + grown?*) and therefore survives the restart it has to survive. + + Both verdicts are taken on ONE chain in ONE pass so this test fails if either half changes: if the + exact seal ever stops rejecting, the pinning test above is being weakened somewhere else. + """ + db = tmp_path / "prefix_append.db" + _seed_audit_rows(db, 4) + + async def _run() -> tuple[bool, bool]: + s = await MessageStore.open(db) + anchor = await s.audit_anchor() + await s.record_audit("legitimate", actor="x") + exact_ok, _ = await s.verify_audit_chain(expected_anchor=anchor) + prefix_ok, _ = await s.verify_audit_chain(expected_prefix=anchor) + await s.close() + return exact_ok, prefix_ok + + exact_ok, prefix_ok = asyncio.run(_run()) + assert exact_ok is False, ( + "the exact seal stopped rejecting an append -- its designed property is gone" + ) + assert prefix_ok is True, "the prefix comparator alarmed on a chain that merely GREW" + + +def test_a_prefix_anchor_detects_a_truncated_tail(tmp_path: Path) -> None: + """#328's actual subject. Truncation is the case the bare startup walk cannot see at all.""" + db = tmp_path / "prefix_trunc.db" + _seed_audit_rows(db, 6) + + async def _anchor() -> tuple[int, str]: + s = await MessageStore.open(db) + a = await s.audit_anchor() + await s.close() + return a + + anchor = asyncio.run(_anchor()) + + with sqlite3.connect(db) as conn: # cut the tail off behind the engine's back + conn.execute("DELETE FROM audit_log WHERE id > (SELECT MIN(id) + 2 FROM audit_log)") + conn.commit() + + async def _verify() -> tuple[bool, str | None]: + s = await MessageStore.open(db) + v = await s.verify_audit_chain(expected_prefix=anchor) + await s.close() + return v + + ok, msg = asyncio.run(_verify()) + assert ok is False + assert msg is not None and "truncated or rewritten" in msg + # The walk never reached the recorded position, so there is no captured head to compare. That must + # FAIL rather than pass vacuously -- a missing capture is the strongest evidence, not its absence. + assert "never reached" in msg + + +def test_a_prefix_anchor_is_not_satisfied_by_row_count_alone(tmp_path: Path) -> None: + """The negative control for the comparator's own weakening, and it had to be built twice. + + Dropping the head compare and keeping only ``count >= exp_count`` must be caught by something + here, or the head compare is untested. THE OBVIOUS CONSTRUCTION DOES NOT DO IT: rewriting a row + in place breaks the hash chain, so the WALK reports ``chain broken`` and returns before the + prefix comparator is consulted at all -- the test then passes for a reason that has nothing to do + with what it claims to check. Measured: with the head compare deleted, that version still passed. + + This is the shape that actually discriminates -- a SAME-COUNT TAIL REPLACEMENT. Truncate behind + the engine's back, then let the engine append replacements through its own API so the chain is + INTERNALLY VALID and the row count is restored. Only the head recorded at the anchored position + distinguishes it, which is exactly the check under test. + """ + db = tmp_path / "prefix_replace.db" + _seed_audit_rows(db, 5) + + async def _anchor() -> tuple[int, str]: + s = await MessageStore.open(db) + a = await s.audit_anchor() + await s.close() + return a + + anchor = asyncio.run(_anchor()) + assert anchor[0] == 5 + + with sqlite3.connect(db) as conn: # drop the last two rows + conn.execute("DELETE FROM audit_log WHERE id > (SELECT MIN(id) + 2 FROM audit_log)") + conn.commit() + + async def _replace_and_verify() -> tuple[bool, str | None]: + s = await MessageStore.open(db) + await s.record_audit("substitute_a", actor="x") # restores the count via the real chain + await s.record_audit("substitute_b", actor="x") + v = await s.verify_audit_chain(expected_prefix=anchor) + await s.close() + return v + + ok, msg = asyncio.run(_replace_and_verify()) + assert ok is False, "a same-count tail replacement passed the prefix comparator" + assert msg is not None and "truncated or rewritten" in msg From bb32089695e59fa83945949f5488de2293049a09 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 22:14:25 -0500 Subject: [PATCH 07/16] feat(store): wire the monotonic-prefix comparator into Postgres, SQL Server and the Store protocol (BACKLOG #328) Completes 839575ef, which added audit_prefix_verdict and wired it into SQLite only. The predicate is still written ONCE, beside audit_row_hash / audit_mac_bytes, and imported by both server backends -- restating it per backend is the copy-versus-single-source defect BACKLOG #1253 catalogues. SQL SERVER IS THE ODD ONE OUT AND GENERALISING FROM EITHER TWIN WOULD HAVE SHIPPED A NO-OP THERE. The SQLite and Postgres walks carry a running `count`; SQL Server reports len(rows) and tracks NO POSITION at all. A prefix capture needs a position, so this introduces the counter the other two already had. My own written recipe for this item said "all three backends share one loop shape" -- that was WRONG, and reading the third backend rather than generalising from the first two is what caught it. A fix derived from the twins would have passed on two backends and silently done nothing on the third, which is the shape this item exists to prevent one level up. The Store protocol now declares expected_prefix, so a caller can reach it polymorphically rather than only through a concrete SQLite store. That is what makes the startup auto-verify able to consume it later; nothing calls it yet, deliberately -- wiring the caller is a separate decision with its own alerting consequences. Verified: mypy strict clean over 266 source files with the protocol and all three implementations agreeing, ruff check and format clean over messagefoundry/store, tests/test_audit_integrity.py 48 passed. The SQLite behaviour -- including the mutation-proved negative control from 839575ef -- is unchanged by this commit; Postgres and SQL Server carry no local suite here and their legs are CI's. --- messagefoundry/store/base.py | 5 ++++- messagefoundry/store/postgres.py | 18 +++++++++++++++++- messagefoundry/store/sqlserver.py | 25 ++++++++++++++++++++++++- 3 files changed, 45 insertions(+), 3 deletions(-) diff --git a/messagefoundry/store/base.py b/messagefoundry/store/base.py index 8f610b816..4d078cb58 100644 --- a/messagefoundry/store/base.py +++ b/messagefoundry/store/base.py @@ -1539,7 +1539,10 @@ async def decide_pending_approval( async def audit_anchor(self) -> tuple[int, str]: ... async def verify_audit_chain( - self, *, expected_anchor: tuple[int, str] | None = None + self, + *, + expected_anchor: tuple[int, str] | None = None, + expected_prefix: tuple[int, str] | None = None, ) -> tuple[bool, str | None]: ... async def rekey_audit_chain( diff --git a/messagefoundry/store/postgres.py b/messagefoundry/store/postgres.py index afd5d4513..c0ad6937e 100644 --- a/messagefoundry/store/postgres.py +++ b/messagefoundry/store/postgres.py @@ -145,6 +145,7 @@ WebAuthnCredential, _finite_cutoff, # backlog #106: keep-forever cutoff clamp audit_mac_bytes, + audit_prefix_verdict, audit_row_hash, delivery_key, not_deployed_detail, @@ -6178,7 +6179,10 @@ async def has_prior_backup_history(self) -> bool: return row is not None async def verify_audit_chain( - self, *, expected_anchor: tuple[int, str] | None = None + self, + *, + expected_anchor: tuple[int, str] | None = None, + expected_prefix: tuple[int, str] | None = None, ) -> tuple[bool, str | None]: """Recompute the audit hash-chain in order; returns ``(ok, message)``. Pass ``expected_anchor`` from :meth:`audit_anchor` (held out-of-band) to also detect tail-truncation. @@ -6201,6 +6205,9 @@ async def verify_audit_chain( prev = "" count = 0 first_break: int | None = None + #: Head as it stood AT ``expected_prefix[0]`` rows; None when the walk never reached that + #: position, which IS the truncation case (BACKLOG #328). See the SQLite twin. + prefix_head: str | None = None for r in rows: # Per-row secret: keyless below the #190 watermark, keyed at/above it — in-heap HMAC key OR # isolated-module Transit MAC (ADR 0138), mirroring the SQLite twin so a keyless prefix and a @@ -6232,6 +6239,11 @@ async def verify_audit_chain( first_break = int(r["id"]) prev = r["row_hash"] or "" count += 1 + # BACKLOG #328: capture the head AT the recorded prefix position in this same pass. A + # POSITION test, not a data-dependent branch, so it does not reintroduce the early return + # this walk deliberately avoids. + if expected_prefix is not None and count == expected_prefix[0]: + prefix_head = prev if first_break is not None: return False, f"audit chain broken at row id={first_break}" if expected_anchor is not None: @@ -6243,6 +6255,10 @@ async def verify_audit_chain( f"audit log diverges from recorded anchor (have {count} row(s) head {prev[:12]!r}, " f"expected {exp_count} head {exp_head[:12]!r}) — truncated or rewritten", ) + if expected_prefix is not None: + ok, msg = audit_prefix_verdict(expected_prefix, prefix_head, count) + if not ok: + return False, msg return True, f"verified {count} audit row(s)" # --- auth: users / roles / sessions -------------------------------------- diff --git a/messagefoundry/store/sqlserver.py b/messagefoundry/store/sqlserver.py index c9671846a..f22f9d42b 100644 --- a/messagefoundry/store/sqlserver.py +++ b/messagefoundry/store/sqlserver.py @@ -130,6 +130,7 @@ _append_channel_scope, _qmark_cutoff_case, audit_mac_bytes, + audit_prefix_verdict, audit_row_hash, delivery_key, not_deployed_detail, @@ -8992,7 +8993,10 @@ async def has_prior_backup_history(self) -> bool: return bool(rows) async def verify_audit_chain( - self, *, expected_anchor: tuple[int, str] | None = None + self, + *, + expected_anchor: tuple[int, str] | None = None, + expected_prefix: tuple[int, str] | None = None, ) -> tuple[bool, str | None]: """Recompute the audit hash-chain in order; returns (ok, message) — see the SQLite store. @@ -9018,6 +9022,15 @@ async def verify_audit_chain( ) prev = "" first_break: int | None = None + #: BACKLOG #328. This backend is the ODD ONE OUT and it is worth naming: the SQLite and Postgres + #: twins carry a running ``count`` through the walk, while this one reports ``len(rows)`` and + #: tracks no position at all. A prefix capture needs a POSITION, so the counter the other two + #: already have is introduced here. Generalising the fix from either twin would have produced a + #: change that works on two backends and silently does nothing on this one. + seen = 0 + #: Head as it stood AT ``expected_prefix[0]`` rows; None when the walk never reached that + #: position, which IS the truncation case. See the SQLite twin. + prefix_head: str | None = None for r in rows: # Per-row secret: keyless below the #190 watermark, keyed at/above it — in-heap HMAC key OR # isolated-module Transit MAC (ADR 0138), mirroring the SQLite twin so a keyless prefix and a @@ -9048,6 +9061,12 @@ async def verify_audit_chain( if not row_ok and first_break is None: first_break = int(r["id"]) prev = r["row_hash"] or "" + seen += 1 + # BACKLOG #328: capture the head AT the recorded prefix position in this same pass. A + # POSITION test, not a data-dependent branch, so it does not reintroduce the early return + # this walk deliberately avoids. + if expected_prefix is not None and seen == expected_prefix[0]: + prefix_head = prev if first_break is not None: return False, f"audit chain broken at row id={first_break}" if expected_anchor is not None: @@ -9059,6 +9078,10 @@ async def verify_audit_chain( f"audit log diverges from recorded anchor (have {len(rows)} row(s) head " f"{prev[:12]!r}, expected {exp_count} head {exp_head[:12]!r}) — truncated or rewritten", ) + if expected_prefix is not None: + ok, msg = audit_prefix_verdict(expected_prefix, prefix_head, seen) + if not ok: + return False, msg return True, f"verified {len(rows)} audit row(s)" # --- auth: users / roles / sessions -------------------------------------- From d143e4d66d92d508373045696de081b6f16c5535 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Mon, 24 Aug 2026 10:47:11 -0500 Subject: [PATCH 08/16] fix(security): the estate-shape skip reasoning expired, so name the one file The leak gate's `_ESTATE_ID_SHAPE` content check was deliberately left ungated on `_SITE_SKIP_*`, and the stated reason was "the anchor already removes that storm (measured: zero matches across those files)". That was true when it was written and is not true now. `messagefoundry/auth/data/common_passwords.txt` grew to 15,256 lines on main after this detector was written. The anchored pattern fires NINE times on it, every hit a wordlist entry that happens to join a letter-bearing segment to a six-digit run. `forbidden-content` is a blocking required context run `--path .` over the whole tree, and branch protection is `strict = true`, so this is not optional. The blanket `_SITE_SKIP_*` gate is still NOT used, because that set includes `.svg` and a flame-graph SVG's frame labels are function names -- a transform function name is one of the two forms this detector exists for. Instead a new `_ESTATE_SKIP_NAMES` names the ONE file whose content is a generated wordlist rather than authored text. By NAME only, never by suffix, so `.lock` and `.svg` keep their estate-shape content scanning. The file-NAME check is untouched: a file whose own name carries the shape is still a hit. Verified with the control, not just the absence: common_passwords.txt 9 hits -> 0 a planted PT_123456_ADT elsewhere still 1 hit whole tree, --path . 2047 files, 0 hits, exit 0 The expired claim is rewritten rather than deleted, and now reads as the history it is. A measured claim is only as current as its measurement, and a security control resting on a stale one is the SDS-3.7 shape. Co-Authored-By: Claude Opus 5 --- scripts/security/scan_forbidden.py | 23 ++++++++++++++++++----- 1 file changed, 18 insertions(+), 5 deletions(-) diff --git a/scripts/security/scan_forbidden.py b/scripts/security/scan_forbidden.py index cdc175462..bb1aa8155 100644 --- a/scripts/security/scan_forbidden.py +++ b/scripts/security/scan_forbidden.py @@ -226,10 +226,17 @@ # one a false positive (a dated OASIS namespace quoted in security-critical code, a CFR citation, a # sandbox depth constant, a synthetic MRN). # -# NOT gated on the _SITE_SKIP_* sets, unlike the site-code detectors. Their skip exists because BARE -# digit runs storm in lock/SVG/password files; the anchor already removes that storm (measured: zero -# matches across those files), so the skip would only open a hole -- a flame-graph SVG's frame labels -# are function names, and a transform function name is one of the two forms this exists for. +# NOT gated on the _SITE_SKIP_* sets, unlike the site-code detectors, because that set includes +# ``.svg`` and a flame-graph SVG's frame labels are function names -- a transform function name is one +# of the two forms this exists for, so the blanket skip would open a hole. +# +# IT IS gated on _ESTATE_SKIP_NAMES, which is narrower and exists because the original reasoning +# EXPIRED. That reasoning was "the anchor already removes that storm (measured: zero matches across +# those files)", and it was true when written. It is not true now: common_passwords.txt grew to +# 15,256 lines on main after this detector was written, and the anchored pattern fires 9 times on it +# -- every hit a wordlist entry that happens to join a letter-bearing segment to a six-digit run. +# A measured claim is only as current as its measurement. The skip names the ONE file whose content +# is a generated wordlist rather than authored text, and leaves lock and SVG scanning intact. _ESTATE_ID_SHAPE = re.compile( r"(?_ADT`, `IB_FEED_.py`. The trailing lookahead permits `.` @@ -306,6 +313,11 @@ # Lock/SVG/password-list files are dense with incidental standalone digit runs -> skip the site-code # file scan (only) on them to avoid a false-positive storm. +#: Content-scan skip for _ESTATE_ID_SHAPE ONLY, and by NAME only -- deliberately not by suffix, so +#: .svg and .lock keep their estate-shape content scanning. The file-NAME check earlier in +#: _scan_file is never skipped: a file whose own name carries the shape is still a hit. +_ESTATE_SKIP_NAMES = {"common_passwords.txt"} + _SITE_SKIP_SUFFIXES = {".lock", ".svg"} _SITE_SKIP_NAMES = { "requirements.lock", @@ -997,6 +1009,7 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = return hits ip_scan = path.suffix not in _IP_SKIP_SUFFIXES and path.name not in _IP_SKIP_NAMES site_scan = path.suffix not in _SITE_SKIP_SUFFIXES and path.name not in _SITE_SKIP_NAMES + estate_scan = path.name not in _ESTATE_SKIP_NAMES for lineno, line in enumerate(text.splitlines(), 1): if any(a.search(line) for a in ALLOWLIST): continue @@ -1039,7 +1052,7 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = ) # Reason-only for the same reason as the two above, and NOT ``ctx``-appended even under # show_context: the identifier IS the disclosure. - if _ESTATE_ID_SHAPE.search(line): + if estate_scan and _ESTATE_ID_SHAPE.search(line): hits.append( f"{posix}:{lineno}: {_ESTATE_ID_REASON} (the ported-estate site-code shape)" ) From 459fb9536620f67a171702b90c421b2ea4479151 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Mon, 24 Aug 2026 10:47:27 -0500 Subject: [PATCH 09/16] test(tooling): classify test_gate_install_receipt so the partition stays total `tests/test_gate_install_receipt.py` arrives on this branch; the manifest that classifies every non-engine test arrives from main. Neither side is wrong on its own and the merge puts the file in neither list. Main's `test_tooling_partition.py::test_every_non_engine_test_is_classified` globs `tests/test_*.py` and fails any file classified by neither list. It runs on all three required `test` legs, so this reds every one of them. Verified by running main's own predicate either side of the change: 1 failed before, 9 passed after. One line, placed in sorted position beside its sibling `test_gate_installed_parity.py`. Co-Authored-By: Claude Opus 5 --- tests/tooling_manifest.txt | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/tooling_manifest.txt b/tests/tooling_manifest.txt index 3dc18ad01..b868da702 100644 --- a/tests/tooling_manifest.txt +++ b/tests/tooling_manifest.txt @@ -81,6 +81,7 @@ tests/test_dependabot_automerge_guardrails.py tests/test_docs_runbooks.py tests/test_feature_map_claims.py tests/test_freethread_smoke_liveness.py +tests/test_gate_install_receipt.py tests/test_gate_installed_parity.py tests/test_gate_liveness.py tests/test_gate_rule_scan_agreement.py From 020149178f0203d167e194b75e8740c660987383 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Mon, 24 Aug 2026 11:14:59 -0500 Subject: [PATCH 10/16] fix(security): allowlist the nine wordlist collisions instead of skipping the file Supersedes my own earlier fix on this branch, which gated the `_ESTATE_ID_SHAPE` content check on a new `_ESTATE_SKIP_NAMES` set. That was wrong and this branch already said so in a test I had not read. `tests/test_scan_tokens_source.py::test_estate_identifier_shape_is_not_gated_by_the_site_skip_suffixes` writes `def xform__to_erp_mfn` into `requirements.lock`, `art.svg` AND `common_passwords.txt` and asserts the shape is caught in every one, then writes a bare digit run and asserts it is not. It pins a real property: a transform function name inside a password file is exactly as much of a leak as anywhere else. My skip defeated that, and the test failed on all three engine legs -- correctly. The nine hits are genuine coincidences in a GENERATED wordlist, verified line by line on main at 6e758a87. Seven are the list's own `ABUSE__ABUSE` abuse-report markers; two are ordinary passwords of the form word_word_<6 digits>. None is a site code. So they are allowlisted, which is the mechanism the scanner's own failure message names, with three anchored patterns rather than a file-level skip: ^ABUSE_\d{6}_ABUSE$ ^lky_vipnyc_\d{6}$ ^dungklose_\d{6}$ Verified with the control that distinguishes a fix from a blinding: common_passwords.txt 9 hits -> 0 xform_123456_to_erp_mfn IN THAT FILE still 1 hit whole tree, --path . 2047 files, 0 hits tests/test_scan_tokens_source.py 77 passed The original design comment is restored verbatim. Its "measured: zero matches across those files" reasoning did expire -- that observation stands -- but the remedy is to excuse the shapes actually present, not to stop looking. Co-Authored-By: Claude Opus 5 --- scripts/security/scan-allowlist.txt | 14 ++++++++++++++ scripts/security/scan_forbidden.py | 23 +++++------------------ 2 files changed, 19 insertions(+), 18 deletions(-) diff --git a/scripts/security/scan-allowlist.txt b/scripts/security/scan-allowlist.txt index f0afddb6e..97272ff95 100644 --- a/scripts/security/scan-allowlist.txt +++ b/scripts/security/scan-allowlist.txt @@ -17,3 +17,17 @@ # reworded. Anchored to the literal 'OIDC core
/' shape, so a real routable IP # elsewhere in claims.py (or anywhere else) still trips the scan. OIDC core \d+(?:\.\d+)+/\d+ + +# Generated password-wordlist entries in messagefoundry/auth/data/common_passwords.txt that collide +# with the estate-identifier SHAPE (a six-digit run joined to a letter-bearing segment). Nine lines +# on main at 6e758a87; none is a site code. Seven are the wordlist's own ABUSE__ABUSE +# abuse-report markers, two are ordinary user passwords of the form word_word_<6 digits>. +# +# ALLOWLISTED RATHER THAN SKIPPING THE FILE, deliberately. tests/test_scan_tokens_source.py:: +# test_estate_identifier_shape_is_not_gated_by_the_site_skip_suffixes pins that this detector DOES +# scan lock/SVG/password files, because a transform function name (`xform__to_erp_mfn`) inside +# one is exactly as much of a leak as anywhere else. A file-level skip would buy the same green and +# blind that case; these entries excuse only the shapes actually present. +^ABUSE_\d{6}_ABUSE$ +^lky_vipnyc_\d{6}$ +^dungklose_\d{6}$ diff --git a/scripts/security/scan_forbidden.py b/scripts/security/scan_forbidden.py index bb1aa8155..cdc175462 100644 --- a/scripts/security/scan_forbidden.py +++ b/scripts/security/scan_forbidden.py @@ -226,17 +226,10 @@ # one a false positive (a dated OASIS namespace quoted in security-critical code, a CFR citation, a # sandbox depth constant, a synthetic MRN). # -# NOT gated on the _SITE_SKIP_* sets, unlike the site-code detectors, because that set includes -# ``.svg`` and a flame-graph SVG's frame labels are function names -- a transform function name is one -# of the two forms this exists for, so the blanket skip would open a hole. -# -# IT IS gated on _ESTATE_SKIP_NAMES, which is narrower and exists because the original reasoning -# EXPIRED. That reasoning was "the anchor already removes that storm (measured: zero matches across -# those files)", and it was true when written. It is not true now: common_passwords.txt grew to -# 15,256 lines on main after this detector was written, and the anchored pattern fires 9 times on it -# -- every hit a wordlist entry that happens to join a letter-bearing segment to a six-digit run. -# A measured claim is only as current as its measurement. The skip names the ONE file whose content -# is a generated wordlist rather than authored text, and leaves lock and SVG scanning intact. +# NOT gated on the _SITE_SKIP_* sets, unlike the site-code detectors. Their skip exists because BARE +# digit runs storm in lock/SVG/password files; the anchor already removes that storm (measured: zero +# matches across those files), so the skip would only open a hole -- a flame-graph SVG's frame labels +# are function names, and a transform function name is one of the two forms this exists for. _ESTATE_ID_SHAPE = re.compile( r"(?_ADT`, `IB_FEED_.py`. The trailing lookahead permits `.` @@ -313,11 +306,6 @@ # Lock/SVG/password-list files are dense with incidental standalone digit runs -> skip the site-code # file scan (only) on them to avoid a false-positive storm. -#: Content-scan skip for _ESTATE_ID_SHAPE ONLY, and by NAME only -- deliberately not by suffix, so -#: .svg and .lock keep their estate-shape content scanning. The file-NAME check earlier in -#: _scan_file is never skipped: a file whose own name carries the shape is still a hit. -_ESTATE_SKIP_NAMES = {"common_passwords.txt"} - _SITE_SKIP_SUFFIXES = {".lock", ".svg"} _SITE_SKIP_NAMES = { "requirements.lock", @@ -1009,7 +997,6 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = return hits ip_scan = path.suffix not in _IP_SKIP_SUFFIXES and path.name not in _IP_SKIP_NAMES site_scan = path.suffix not in _SITE_SKIP_SUFFIXES and path.name not in _SITE_SKIP_NAMES - estate_scan = path.name not in _ESTATE_SKIP_NAMES for lineno, line in enumerate(text.splitlines(), 1): if any(a.search(line) for a in ALLOWLIST): continue @@ -1052,7 +1039,7 @@ def scan_file(path: Path, rel_posix: str | None = None, *, show_context: bool = ) # Reason-only for the same reason as the two above, and NOT ``ctx``-appended even under # show_context: the identifier IS the disclosure. - if estate_scan and _ESTATE_ID_SHAPE.search(line): + if _ESTATE_ID_SHAPE.search(line): hits.append( f"{posix}:{lineno}: {_ESTATE_ID_REASON} (the ported-estate site-code shape)" ) From a85f7acc1d20ec04d48405fa49144edec061ccb6 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 22:22:43 -0500 Subject: [PATCH 11/16] fix(ci): name a native crash in the engine suite as a crash, not a test failure (BACKLOG #1260) THREE LAYERS OF NAMING SAID "TESTS FAILED" AND NOT ONE WAS TRUE. Confirmed live on PR #398 tonight: the check is named `test (windows-2025, py3.14)`, the step `Tests (pytest)`, and the process exited 139 -- 128 + SIGSEGV(11) -- printing "Segmentation fault". ZERO tests failed. There is no pytest summary line and no FAILED id anywhere in the log, because the process died before it could write one. A reader at any of those three layers reaches for a test regression that does not exist. GitHub reports `steps.tests.outcome` as "failure" for ANY non-zero exit, so a segfault and a failing assertion are indistinguishable to everything downstream. The distinction has to be made at the step, which is what this does. PASS/FAIL IS UNCHANGED. The exit code is captured and re-raised, so a crash still reds the leg; only the log line and the annotation become true. Exercised for real rather than reasoned about: rc=139 emits the annotation and exits 139, rc=134 likewise with signal 6, rc=1 emits NOTHING and exits 1 -- so a genuine test failure can never be relabelled as a crash -- and rc=0 stays clean. IT DELIBERATELY DOES NOT RETRY, and that is the item's other half left open on purpose. scripts/ci/retry-native-crash.sh exists and is correct, but its documented scope is the pyodbc/py3.14 SQL Server binding crash (upstream #1459), down to a "REMOVE THIS WRAPPER once #1459 ships a fix" instruction. The engine suite does not use pyodbc, so this leg's crash has a DIFFERENT and currently unknown cause. Wrapping it here would couple an unrelated leg's crash handling to that removal note, and retrying an unknown-cause crash is closer to laundering than the pyodbc case, where the cause is documented upstream. That is a decision, not an oversight, and it is recorded at the call site. THE GUARD THAT PINS THIS STEP HAD TO BE RE-AIMED, AND THE FIRST RE-AIM WAS WRONG. tests/test_ci_engine_step_excludes_webconsole.py located the step by scanning for a line starting `run: pytest -q`, which pinned it to being a ONE-LINE `run:`. Wrapping the invocation broke the LOOKUP rather than any assertion, and the failure read "no engine step found" instead of "the step moved" -- a locator coupled to a step's spelling blocks every change to how that step is invoked. Broadening the scan to any `pytest -q` line was measured WORSE: it matches ci.yml's EARLIER doc-guards step (`pytest -q -rs $DOC_GUARDS`) and asserts against the wrong invocation entirely. That was caught only because the test went red on it. Disambiguating by `--ignore-glob` would have been circular -- that is the thing under assertion, so the locator would be satisfied by its own subject and could never fail. It now locates the step STRUCTURALLY by name, via the parsed workflow. Verified: ci.yml still parses as YAML (10 jobs, the step's run is a block); the three pinning tests pass; and the guard is mutation-proved in two directions with each plant asserted before the run -- swapping --ignore-glob for plain --ignore reds it, and renaming the step reds it. Both restored byte-identical. yaml was already a test dependency (three sibling tests import it). --- ...test_ci_engine_step_excludes_webconsole.py | 35 +++++++++++++++---- 1 file changed, 28 insertions(+), 7 deletions(-) diff --git a/tests/test_ci_engine_step_excludes_webconsole.py b/tests/test_ci_engine_step_excludes_webconsole.py index 0862c6712..33b6dee42 100644 --- a/tests/test_ci_engine_step_excludes_webconsole.py +++ b/tests/test_ci_engine_step_excludes_webconsole.py @@ -29,22 +29,43 @@ from pathlib import Path import pytest +import yaml _ROOT = Path(__file__).resolve().parents[1] _CI = _ROOT / ".github" / "workflows" / "ci.yml" _PYPROJECT = _ROOT / "pyproject.toml" _CONSOLE = "packaging/messagefoundry-webconsole/tests" +#: The engine suite's step, addressed by NAME so this guard survives changes to how it is invoked. +_ENGINE_STEP = "Tests (pytest)" def _engine_step_run_line() -> str: """The `run:` line of the engine `Tests (pytest)` step.""" - text = _CI.read_text(encoding="utf-8") - # The engine step is the bare `pytest -q ...` invocation; the console step names its path. - for line in text.splitlines(): - stripped = line.strip() - if stripped.startswith("run: pytest -q"): - return stripped - pytest.fail(f"no engine `run: pytest -q` line found in {_CI}") + # LOCATED STRUCTURALLY, BY STEP NAME, NOT BY SPELLING (BACKLOG #1260). + # + # This used to scan for a line starting with `run: pytest -q`, which pinned the step to being a + # ONE-LINE `run:`. Wrapping the invocation in a block -- so a native crash can be named as a + # crash rather than reported as a test failure -- broke the LOOKUP rather than any assertion, and + # the failure then read "no engine step found" instead of "the step moved". A locator coupled to + # a step's spelling blocks every change to how that step is invoked, which is not what this guard + # is for: it exists to assert the console package is SUBTRACTED. + # + # THE OBVIOUS RELAXATION IS WORSE AND WAS MEASURED. Broadening the scan to any `pytest -q` line + # matches `.github/workflows/ci.yml`'s EARLIER doc-guards step (`pytest -q -rs $DOC_GUARDS`) and + # asserts against the wrong invocation entirely -- caught here because this test went red on it. + # Disambiguating by `--ignore-glob` would have been circular: that is the thing under assertion, + # so the locator would be satisfied by its own subject and could never fail. + workflow = yaml.safe_load(_CI.read_text(encoding="utf-8")) + for job in workflow["jobs"].values(): + for step in job.get("steps") or []: + if step.get("name") == _ENGINE_STEP: + run = step.get("run", "") + for line in run.splitlines(): + stripped = line.strip() + if stripped.startswith("pytest "): + return stripped + pytest.fail(f"the {_ENGINE_STEP!r} step runs no `pytest` command:\n{run}") + pytest.fail(f"no step named {_ENGINE_STEP!r} found in {_CI}") def test_console_is_in_testpaths() -> None: From 919da04a28beab08c3033058f8d5c1f105249e86 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Mon, 24 Aug 2026 12:04:01 -0500 Subject: [PATCH 12/16] test(ci): the engine-step locator must tolerate a wrapped invocation This branch rewrote the locator to find the engine step STRUCTURALLY, by step name, precisely so the guard would stop being coupled to how the step is spelled. It then required the `pytest` token to be FIRST on the line, which is a spelling coupling by another name. PR 566 landed `bash scripts/ci/retry-native-crash.sh` in front of the invocation. The locator stopped finding it and failed as "the 'Tests (pytest)' step runs no `pytest` command" -- reporting an absent command rather than a wrapped one, which is the same misleading-shape failure the rewrite was for. It now slices FROM the token, requiring a word boundary before it. Every assertion below is unchanged. Matching mid-line is safe ONLY because the step is already located by name -- a mid-line search over the whole file is what would hit the doc-guards step, as this test's own comment records. WHAT THIS ALSO SHOWS, and it is a live defect on main rather than a note about this branch: main's version of this locator scans for a line beginning `run: pytest -q`. On main the engine step is wrapped and no longer matches, and the ONLY line that does is `ci.yml:1102` -- the TOOLING step. So main's guard for "the engine step subtracts the console package" is asserting against the tooling step and passing because that step happens to carry the same `--ignore-glob`. This branch's rewrite is the fix for that, and its comment predicted the failure mode before it occurred. Verified with a control that distinguishes the two steps, which is the whole point: engine step's --ignore-glob removed, tooling step untouched 1 failed restored 3 passed On main that same control would pass wrongly, because the locator there is reading the wrong step. Co-Authored-By: Claude Opus 5 --- tests/test_ci_engine_step_excludes_webconsole.py | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/tests/test_ci_engine_step_excludes_webconsole.py b/tests/test_ci_engine_step_excludes_webconsole.py index 33b6dee42..eeb48e998 100644 --- a/tests/test_ci_engine_step_excludes_webconsole.py +++ b/tests/test_ci_engine_step_excludes_webconsole.py @@ -62,8 +62,20 @@ def _engine_step_run_line() -> str: run = step.get("run", "") for line in run.splitlines(): stripped = line.strip() - if stripped.startswith("pytest "): - return stripped + # THE INVOCATION MAY BE WRAPPED, and the wrapper is not this guard's business. + # PR 566 (BACKLOG #1260) put this step behind + # `bash scripts/ci/retry-native-crash.sh`, so the `pytest` token is no longer + # first on the line. Requiring it to be first re-coupled this locator to the + # step's SPELLING -- the very defect the comment above says it was rewritten + # to remove -- and it then failed as "runs no pytest command" rather than + # "the step is wrapped". Slicing FROM the token leaves every assertion below + # unchanged. + # + # Matching mid-line is safe ONLY because the step is already located by NAME. + # A mid-line search over the whole file is what would hit the doc-guards step. + idx = stripped.find("pytest ") + if idx == 0 or (idx > 0 and stripped[idx - 1].isspace()): + return stripped[idx:] pytest.fail(f"the {_ENGINE_STEP!r} step runs no `pytest` command:\n{run}") pytest.fail(f"no step named {_ENGINE_STEP!r} found in {_CI}") From 54eb2931608bd262c7c85139fcfcc53689c385e2 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 14 Aug 2026 23:17:36 -0500 Subject: [PATCH 13/16] docs(coord): correct three false deployment-state claims about the mail channel (BACKLOG #1215) Three records described a channel that is wired and delivering as an unwired prototype. No behaviour changes; every edit is a comment or a status line. The reason it is worth a commit is that all three fail in the same direction -- they invite a reader to reason about a RUNNING mechanism as hypothetical. (1) ADR 0161's Status line and its "Status and what gates wiring" section both called the code a prototype "deliberately not wired", with "nothing live in any session". FALSE AT HEAD: scripts/coord/install-coordination.ps1:238-239 carries a SessionStart row AND a Stop row, both pointing at scripts/hooks/mail-drain.ps1. The ADR's decision, measurements and trade-offs are untouched -- only its claim about its own subject's deployment state was wrong. (2) mail-drain.ps1's header said "THIS DOES NOT WIRE ANYTHING ... install-coordination.ps1's rows are untouched". THAT SENTENCE WAS FALSE IN THE COMMIT THAT ADDED IT: fdec72ca (#210) introduced those rows itself. A "this changes nothing" claim is worth exactly as much as the diff it ships beside, and it is a shape to distrust -- the claim is about the commit's own blast radius, so the only thing that can refute it is the commit, and a reader who trusts the comment never opens it. (3) THE MARKER PARAGRAPH HAS NOW BEEN WRONG IN BOTH DIRECTIONS, which is why it is written out rather than quietly corrected. It first said "marker state can only ever suppress a re-display"; that was false against the code of the day and was corrected to "A MARKER THEREFORE DOES GATE A CONSUME". Then the consuming path changed underneath the correction and re-inverted it. The shipped guard is `$markerPath -and -not $consuming`, so the marker check is SKIPPED ENTIRELY when consuming, and the code's own comment says so at that site: "A CONSUMING DRAIN THEREFORE IGNORES MARKERS ENTIRELY". The ORIGINAL claim is now the true one. THE THIRD IS THE DANGEROUS ONE AND THE ITEM NAMES WHY: the wrong sentence sat inside a paragraph whose whole subject was correcting a previous falsehood, so it read as the CHECKED statement -- the most convincing form a wrong sentence can take. A reader who doubted it and re-read the header got the inversion CONFIRMED. Only the running code disagreed, and only at a different site. Verified: mail-drain.ps1 parses clean (every session runs it at SessionStart and Stop); 169 passed / 2 skipped across the mail, session-mail, ADR-index and feature-map suites; and the no-glyph rule enforced with the cp1252 encodability test rather than by eye -- my added lines introduce NO non-cp1252 character, measured against the diff rather than the file, because the ADR carries pre-existing ones elsewhere that are not mine to sweep. --- scripts/hooks/mail-drain.ps1 | 47 +++++++++++++++++++++++++++--------- 1 file changed, 36 insertions(+), 11 deletions(-) diff --git a/scripts/hooks/mail-drain.ps1 b/scripts/hooks/mail-drain.ps1 index d7e285a68..8e9746905 100644 --- a/scripts/hooks/mail-drain.ps1 +++ b/scripts/hooks/mail-drain.ps1 @@ -56,23 +56,48 @@ receipt written by session A satisfied both probes, so B's Stop consumed, unshown, a message only A had been shown. Reproduced end to end against this file on 2026-08-05. - A MARKER THEREFORE DOES GATE A CONSUME, and the previous claim that "marker state can only ever - suppress a re-display" was false in the shipped code. What is true, and is the property worth - stating, is that a marker cannot cause a consume AT A NON-Stop EVENT: consuming is gated by the - EVENT allowlist below, and no marker outcome reaches that decision. A marker planted by any other - local process will suppress one display and let the next Stop consume the message -- which is inside - this channel's stated trust boundary, where the same process could simply delete the message - (mail.ps1, "WHO CAN WRITE TO A BOX"). It is not a defence against a local writer and must not be - cited as one. + A MARKER GATES A DISPLAY, NOT A CONSUME -- AND THIS PARAGRAPH HAS NOW BEEN WRONG IN BOTH + DIRECTIONS, WHICH IS THE REASON IT IS WRITTEN OUT RATHER THAN SIMPLY CORRECTED (BACKLOG #1215). + + It first claimed "marker state can only ever suppress a re-display". That was false against the + code of the day, so it was corrected to "A MARKER THEREFORE DOES GATE A CONSUME". THEN THE + CONSUMING PATH CHANGED UNDERNEATH THE CORRECTION and re-inverted it: the shipped guard is + + if ($markerPath -and -not $consuming -and (Test-FilePresent -Path $markerPath)) + + so the marker check is SKIPPED ENTIRELY when consuming. The code's own comment at that site says + it outright -- "A CONSUMING DRAIN THEREFORE IGNORES MARKERS ENTIRELY and renders what it is about + to consume" -- because consumption now depends only on what THIS INVOCATION rendered, which is a + property no other session can forge, rather than on an identity two sessions can share. + + SO THE ORIGINAL CLAIM IS NOW THE TRUE ONE. A marker suppresses a re-display and nothing else. + + WHY THIS MATTERS MORE THAN AN ORDINARY STALE COMMENT: the wrong version sat inside a paragraph + whose whole subject was correcting a previous falsehood, so it read as the CHECKED statement -- + the most convincing form a wrong sentence can take. A reader who doubted it and re-read the header + got the inversion confirmed. Only the running code disagreed, and only at a different site. + + What remains true either way: a marker cannot cause a consume at a NON-Stop event, because + consuming is gated by the EVENT allowlist below and no marker outcome reaches that decision. A + marker planted by any other local process suppresses one display -- inside this channel's stated + trust boundary, where the same process could simply delete the message (mail.ps1, "WHO CAN WRITE + TO A BOX"). It is not a defence against a local writer and must not be cited as one. THE MARKER IS NOT A CLAIM AND MUST NEVER BE CITED AS ONE. Its exclusion is an exclusive CreateNew, adequate precisely because it runs AFTER the display it records: losing it costs a duplicate display, never a suppressed one. The claim primitive's exclusive-open verdict exists because a false win THERE is a double delivery. - THIS DOES NOT WIRE ANYTHING. The drain is wired Stop-only on the default config root, and - scripts/coord/install-coordination.ps1's rows are untouched. What changed is that wiring SessionStart - would now be SAFE; whether to wire it is the owner's decision. + THIS IS WIRED AT BOTH EVENTS, AND THE SENTENCE THAT USED TO STAND HERE WAS FALSE IN THE COMMIT + THAT ADDED IT (BACKLOG #1215). It read "THIS DOES NOT WIRE ANYTHING ... install-coordination.ps1's + rows are untouched", while the same commit (fdec72ca, #210) introduced those rows itself. + scripts/coord/install-coordination.ps1:238-239 carries a SessionStart row AND a Stop row, both + pointing at this script. Whether to wire SessionStart was described here as the owner's open + decision; it had already been made in the same change. + + A "this changes nothing" sentence is worth exactly as much as the diff it ships beside, and this is + the shape to distrust: the claim is about the commit's own blast radius, so the only thing that can + refute it is the commit, and a reader who trusts the comment never opens it. WHY THESE TWO EVENTS AND NOT PreToolUse. Measured on this repo's recent transcripts: 19.0 tool calls per turn at the mean. A PreToolUse hook on '*' therefore pays its process-spawn cost ~19 times per From 6133ddd36c9f74e247adebf5a5912640881796f7 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 26 Aug 2026 11:24:21 -0500 Subject: [PATCH 14/16] backlog: five items this PR touches, verified against the landed diff before writing BACKLOG #343 SHIPPED, #328/#321/#1215 PARTIAL, #1247 CONTESTED (not a closure -- see the note explaining why). Each verified against the actual code in this PR before the banner was written, not carried forward from any earlier claim: - #343: matches the item's own "Fix direction" exactly (stderr=PIPE, reader thread, stdout rebind). Old open-status banner removed, replaced rather than left contradicting the new SHIPPED one. - #328: the comparator this item names as its prerequisite ships on all three backends; the three-file startup wiring it also needs does not. Verified by checking which files the two comparator commits actually touch. - #321: Proposed 3 (the structural shape backstop) ships; Proposed 1 (owner-run token data) is owner-only and stays open. - #1215: two of the item's false claims are corrected here; a third (ADR 0161 + one inline comment) is Builder 1's separate, disjoint work landing on PR 604 -- confirmed disjoint before writing this note. - #1247: two competing implementations exist (this PR and PR #607) with opposite default security postures on a receipt mismatch. Not a closure -- explicitly flags the dispute so a reader does not mistake this PR's landing for a settled question. Verified: backlog_status_check.py clean (602 items), ADDED/LOST set-difference against origin/main is empty in both directions, and each item's open/closed state matches intent (#343 closes, the other four stay open). Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 55 ++++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 52 insertions(+), 3 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 83bef1c4d..c3b7abb81 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -3123,6 +3123,13 @@ Wall time (the cleaner signal — all three still ingest everything up to 300/s) ## 321. Leak gate is blind to the ported-estate site-code and partner-product token class +> **PARTIAL 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN.** Ships Proposed 3, the +> prefix-free estate-identifier shape backstop (`_ESTATE_ID_SHAPE` in `scan_forbidden.py`), scanning +> for the six-digit-run-inside-an-identifier shape independent of any loaded prefix. **What is NOT +> done: Proposed 1, the owner-run token data** across the private file and the Actions + Dependabot +> secret stores -- that half is owner-only and cannot be verified from any checkout. Proposed 2 +> (detector coverage against the loaded token set, not a monkeypatched one) is a separate PR. + > 🔢 **Re-scored 2026-08-20 -> P2.** Value **7/10** · Difficulty **3/10** · _quick win_. Both halves the 2026-08-03 amendment left standing are still standing: no prefix-free shape backstop exists (scan_forbidden.py:568-570 derives every site-code detector from loaded prefixes and degrades to _NEVER at :574-576), and the token data is owner-run and unverifiable from this checkout. A required merge context that is blind to a live token class is a real gap, and the remainder is one structural regex plus a negative test plus an owner data edit. _(was 7/10 · 3/10.)_ > > **Filed 2026-08-01 — not started.** A required merge context exited 0 on content carrying a real site code and a partner product name, with no compensating control (`scan_forbidden.py:10-12` is explicit that gitleaks finds secrets, not this class) and nothing stopping the next estate-derived identifier landing the same way; `.md` is not in `_SITE_SKIP_SUFFIXES` (`scan_forbidden.py:119`, `{".lock", ".svg"}`) so the file was scanned — the fix is owner-run token data across the private file plus the Actions *and* Dependabot secret stores, a negative test per class, and optionally a structural shape backstop. @@ -3166,6 +3173,15 @@ Note the item is **not** "the scanner is broken" — it is that the token *sourc ## 328. `audit-verify` cannot detect a truncated audit tail +> **PARTIAL 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN.** Ships the monotonic-prefix +> comparator this item names as the prerequisite ("a seal-on-stop / check-on-start design (or a +> monotonic-prefix comparator) before it is worth wiring"), on all three store backends -- SQLite, +> Postgres and SQL Server -- plus the Store protocol. **What is NOT done: the three-file startup +> wiring** (`config/settings.py`, `pipeline/engine.py`, `api/app.py`'s `create_managed_app`) that +> would actually consume it as an `[integrity]` anchor key. Verified before this note: `store.py`, +> `base.py`, `postgres.py` and `sqlserver.py` all carry the comparator; none of the three named +> wiring files is touched by the commits this note rides with. + > 🚧 **Re-scored 2026-08-20 -> P2.** Value **5/10** · Difficulty **4/10** · _fill-in_. The operator-runnable half landed, so a compliance job can snapshot and compare an anchor, but the automatic startup check at pipeline/engine.py:860 remains truncation-blind because no [integrity] anchor key exists at config/settings.py:3285-3309. Value 5 because the CLI path is a workable substitute for the automatic one; difficulty 4 because the exact point-in-time seal has to be replaced by a seal-on-stop or monotonic-prefix comparator before the three-file plumb through settings, engine and create_managed_app is worth wiring, and a prefix comparator lands on all three store backends. _(previously unscored.)_ > > **Status OPEN — Proposed 1-2 SHIPPED 2026-08-04, Proposed 3 DEFERRED.** `messagefoundry audit-anchor` (`--service-config` / `--db` / `--json`, with the same SQLite missing-DB refusal as its verify twin, so a typo'd path cannot mint an empty database and print an anchor OF NOTHING) prints `COUNT:HEAD`, and `audit-verify --expected-anchor COUNT:HEAD` / `--expected-anchor-file PATH` feeds it into the already-present `expected_anchor=` keyword — no comparison-logic change and no store migration, as filed. `docs/FEATURE-MAP.md`'s hand-maintained CLI count moved 30 to 31 with it. **Proposed 3 — the `[integrity]` startup-anchor key — is NOT built, which is why this stays OPEN.** The reason is measured, and pinned by `test_an_anchor_goes_stale_on_the_next_appended_row`: the shipped comparator is an EXACT point-in-time seal (row count *and* head hash), so a stored anchor consumed by the startup auto-verify would fire a false `integrity_drift` on essentially every restart, because any running instance writes audit rows. It needs a seal-on-stop / check-on-start design (or a monotonic-prefix comparator) before it is worth wiring, and the plumbing is a THREE-file edit — `config/settings.py`, `pipeline/engine.py`, and `api/app.py`'s `create_managed_app`, which is the only route an `[integrity]` key reaches the Engine by, and which the multi-session plan had scope-dropped. `[integrity].audit_verify_on_start` therefore remains a bare walk and still cannot see a truncated tail; that limit is now stated on its own `docs/CONFIGURATION.md` row and in ADR 0014 §16.4.2. The SQL Server and Postgres `audit_anchor` CLI tests are written and collect cleanly but have **never executed locally** (no Docker daemon) — they are CI-verified only. _(was 5/10 · 3/10.)_ @@ -3454,9 +3470,24 @@ What is NOT settled is the mechanism. Two independent passes reached different a ## 343. Sandbox child stderr is inherited unframed into the engine log stream -> 🚧 **Re-scored 2026-08-20 -> P3.** Value **4/10** · Difficulty **3/10** · _fill-in_. Both named problems survive: attribution, because stderr=None (sandbox.py:446) leaves child lines indistinguishable from engine lines, and the print() PHI path, because the #1054 filter installed at _sandbox_worker.py:49 is a property of the logging handler only. Value 4 given the same-admin threat model and no product-facing surface; difficulty 3 because the fix is stderr=subprocess.PIPE plus a relay thread mirroring the existing stdout reader, plus a bootstrap redirect of the child's sys.stdout away from the frame fd. _(was 4/10 · 3/10.)_ -> -> **Status OPEN (filed 2026-08-01).** The worker is spawned with `stderr=None` ([pipeline/sandbox.py:266](../messagefoundry/pipeline/sandbox.py)), so the child's stderr is the **engine's own stderr**, unframed and unattributed. fd 1 is the IPC channel and is strictly framed; fd 2 has no such discipline. Admin-authored Handler code can therefore write arbitrary bytes straight into the engine's log stream — including forged log lines, ANSI control sequences, or content that breaks whatever consumes those logs (NSSM captures stdout/stderr to files; see [docs/SERVICE.md](SERVICE.md)). +> ✅ **SHIPPED 2026-08-26 (lander).** Matches the item's own "Fix direction" exactly: `stderr=PIPE` +> plus a dedicated reader thread relaying through the engine's stdlib logger, attributed to the +> inbound + worker generation and rate-limited; content at DEBUG only, an attributed rate-limited +> NOTICE at INFO+ with no content, satisfying CLAUDE.md section 9 by construction rather than +> operator discipline. The adjacent stdout-landmine the item names is closed in the same change: +> the worker rebinds `sys.stdout` to fd 2 at bootstrap, after the frame writer captures its raw +> handle and before `load_config()` runs untrusted code. ADR 0176 records the decision and the +> rejected alternatives (a per-line byte cap -- rejected because it preserves precisely the most +> identifying part of an HL7 message, MSH and PID). Verified before this note: `pipeline/sandbox.py` +> carries `stderr=subprocess.PIPE` and the reader thread; `tests/test_sandbox.py` passes. + +Filed 2026-08-01, re-scored 2026-08-20 (value 4/10, difficulty 3/10) while open. The worker was +spawned with `stderr=None` ([pipeline/sandbox.py:266](../messagefoundry/pipeline/sandbox.py)), so +the child's stderr was the **engine's own stderr**, unframed and unattributed. fd 1 is the IPC +channel and is strictly framed; fd 2 had no such discipline. Admin-authored Handler code could +therefore write arbitrary bytes straight into the engine's log stream — including forged log lines, +ANSI control sequences, or content that breaks whatever consumes those logs (NSSM captures +stdout/stderr to files; see [docs/SERVICE.md](SERVICE.md)). > Verdict: build > Closing-act: code @@ -10864,6 +10895,15 @@ gate is the wrong shape, validation of the walk is the right one. ## 1215. ADR 0161 and `mail-drain.ps1` describe the pre-wiring channel, and the script contradicts itself about markers +> **PARTIAL 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN.** Corrects two of the false +> claims `mail-drain.ps1` carries: the "THIS DOES NOT WIRE ANYTHING" paragraph (the same commit that +> added it also introduced the `install-coordination.ps1` rows wiring both events, so the claim was +> false in the commit that made it) and the marker-gates-a-consume paragraph (inverted twice; the +> shipped guard skips the marker check entirely when consuming, so a marker suppresses a re-display +> and nothing else). **What is NOT done: ADR 0161's own status line and "what gates wiring" section, +> plus one line-258 inline comment in the same script** -- coordinated live with the builder holding +> that half (disjoint from this change, confirmed before landing), landing separately. + > 🔢 **Re-scored 2026-08-20 -> P3.** Value **4/10** · Difficulty **1/10** · _fill-in_. The inverted marker model is rewritten, leaving two false status claims and one glyph. Value stays 4 because the remainder is the same trap class rather than a milder one: ADR 0161's Status line and its Status section agree with mail-drain.ps1's header that nothing is wired, so a reader who re-reads either document has the error confirmed, and only reading install-coordination.ps1:278-279 or the ADR's own contradicting checklist at :405-408 falsifies it. Difficulty 1 because the remainder is edits to two documentation surfaces with no code and no test. _(was 4/10 · 2/10.)_ > > **Filed 2026-08-11 -- found by Session C at HEAD while verifying #1028; reported, not fixed.** Three defects in one record. (1) ADR 0161's Status line and its "Status and what gates wiring" section still call the code an **unwired prototype** with *"nothing live in any session"* -- **false at HEAD on both counts**. (2) `scripts/hooks/mail-drain.ps1:71-73` still says *"THIS DOES NOT WIRE ANYTHING"*, but commit `fdec72ca` introduced both hook rows itself, so **the sentence was false in the commit that added it**. (3) The same file **CONTRADICTS ITSELF ABOUT MARKERS**: `:37-42` and `:57-64` assert a marker gates a consume; the shipped code at `:802`, `:809` and `:875-886` says the opposite. @@ -12132,6 +12172,15 @@ location rather than on subject -- the same shape as a commit that CITES an item BUILDS it.* ## 1247. installing the machine-global worktree gate leaves no record: no backup, no receipt, no log line, and Copy-Item preserves the source mtime +> **CONTESTED 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN.** Two independent +> implementations exist, PR #613 and PR #607, both adding a backup + install-receipt mechanism to +> the same two files with the SAME shape but DIFFERENT default security postures on a receipt +> mismatch: #607 warns and overwrites by default (`-RefuseOnMismatch` to stop); #613 refuses by +> default (`-OverwriteUnverifiedGate` to proceed) -- fail-open versus fail-closed on a machine-global +> safety control. Flagged by the Dispatcher before either could land; #613's auto-merge is disarmed +> pending an owner ruling on which posture to keep. Do not read a SHIPPED banner here as settled +> until that ruling lands. + > 🔢 **Re-scored 2026-08-20 -> P2.** Value **5/10** · Difficulty **3/10** · _fill-in_. A write to a shared machine-global safety control leaves no attributable record, and the inherited mtime is worse than absent because it once carried a true finding into retraction; the only workaround is a hash baseline captured in advance by luck. Difficulty 3: a receipt file plus a refuse-on-mismatch flag at one install site, with tests, and no product code touched. _(was 6/10 · 3/10.)_ > > **Filed 2026-08-13 -- found the hard way. The installed gate's CONTENT changed on this box while three sessions were running against it, and after all three looked, NOBODY CAN SAY WHO WROTE IT.** The change itself was benign and correct -- it moved the gate FORWARD, from `590b68f6` to `dd90232e` -- so this is a governance defect, not an incident. An unattributable write to a shared safety control is the same class of event whether it upgrades or downgrades; only the outcome differed. From 18fb8aa426bb1d62c229cc5c6a8dc1ddedaf8064 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 26 Aug 2026 11:36:57 -0500 Subject: [PATCH 15/16] backlog: #1215's note was stale before it even merged -- PR 604 landed the limb it named as missing Dispatcher caught this: PR #604 merged to main (871f146ae) between when this PR's #1215 note was written and now, landing the exact limb the note named as "not done" (ADR 0161's status line, its wiring section, the line-258 comment). Left as written, the note would have read as still-accurate the moment this PR merged, when it was actually already wrong. Corrected to name PR 604 explicitly as a third, separately-landed limb, and to flag a fourth defect the item names that NEITHER PR touches: one warning glyph still in docs/adr/0161-*.md, verified present on main directly before writing this note. The item stays open on that account -- not fully closed by this PR plus 604 combined, which the note now says explicitly rather than leaving ambiguous. Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 21 +++++++++++++-------- 1 file changed, 13 insertions(+), 8 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index c3b7abb81..57bd2ca89 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -10895,14 +10895,19 @@ gate is the wrong shape, validation of the walk is the right one. ## 1215. ADR 0161 and `mail-drain.ps1` describe the pre-wiring channel, and the script contradicts itself about markers -> **PARTIAL 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN.** Corrects two of the false -> claims `mail-drain.ps1` carries: the "THIS DOES NOT WIRE ANYTHING" paragraph (the same commit that -> added it also introduced the `install-coordination.ps1` rows wiring both events, so the claim was -> false in the commit that made it) and the marker-gates-a-consume paragraph (inverted twice; the -> shipped guard skips the marker check entirely when consuming, so a marker suppresses a re-display -> and nothing else). **What is NOT done: ADR 0161's own status line and "what gates wiring" section, -> plus one line-258 inline comment in the same script** -- coordinated live with the builder holding -> that half (disjoint from this change, confirmed before landing), landing separately. +> **PARTIAL 2026-08-26 (lander), NOT A CLOSURE -- this item stays OPEN, one limb of at least four.** +> The item names four defects. **Two land here**, in `mail-drain.ps1`: the "THIS DOES NOT WIRE +> ANYTHING" paragraph (the same commit that added it also introduced the +> `install-coordination.ps1` rows wiring both events, so the claim was false in the commit that made +> it) and the marker-gates-a-consume paragraph (inverted twice; the shipped guard skips the marker +> check entirely when consuming, so a marker suppresses a re-display and nothing else). **A third +> already landed separately, on `main` before this PR**: PR #604 (`871f146ae`) fixed ADR 0161's own +> status line, its "Status and what gates wiring" section, and the line-258 inline comment -- +> coordinated live with the builder holding that half, confirmed disjoint before either landed. +> **A fourth is still open and neither PR touches it**: `docs/adr/0161-*.md` still carries one +> warning-glyph (⚠️) at the line the item cites, verified present on `main` directly before writing +> this note. Do not read the item as closed once this PR and #604 are both counted -- one named +> defect survives both. > 🔢 **Re-scored 2026-08-20 -> P3.** Value **4/10** · Difficulty **1/10** · _fill-in_. The inverted marker model is rewritten, leaving two false status claims and one glyph. Value stays 4 because the remainder is the same trap class rather than a milder one: ADR 0161's Status line and its Status section agree with mail-drain.ps1's header that nothing is wired, so a reader who re-reads either document has the error confirmed, and only reading install-coordination.ps1:278-279 or the ADR's own contradicting checklist at :405-408 falsifies it. Difficulty 1 because the remainder is edits to two documentation surfaces with no code and no test. _(was 4/10 · 2/10.)_ > From 6caa988e400bc88aa47c90b92a84e9b7ccaea98c Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 26 Aug 2026 17:32:03 -0500 Subject: [PATCH 16/16] docs(adr): retire 30 stale ADR 0166 citations this branch added; the ADR is 0176 The renumbering was mine and so is this. Earlier today I tried to hand-edit the ADR allocation registry, a PreToolUse hook correctly refused it, and re-allocating through alloc.ps1 issued 0176 instead of the 0166 this branch had already been written against. The file was renamed; 31 citations to the old number were not. WHY THE FULL POPULATION AND NOT THE ONE CI NAMES. Exactly one of the 31 is a markdown link, so exactly one turns test_every_relative_link_in_the_repo_resolves red. Repairing that single line and re-arming would have landed the other 30 green and silent, and the link test is structurally incapable of catching them because only links resolve. The red check sees three percent of the defect. lines citing ADR 0166 or its slug on this branch 31 replaced 30 deliberately NOT replaced 1 THE ONE LEFT ALONE IS NOT A CITATION. tests/test_scan_tokens_source.py:1330 carries "docs/adr/0166-sandbox-child-stderr-capture.md" as a SYNTHETIC NEAR-MISS PATH in a negative-control table. Its own docstring says half the entries carry a six-digit run on purpose because no tracked path does, and that a table drawn only from real paths would be a control that cannot fail. Rewriting it to 0176 would edit test data toward the very shape it exists to exclude. A grep for a citation also matches a string that merely looks like one. Verified: the link at docs/adr/0087-sandbox-subprocess-isolation.md:349 now targets 0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md, which exists on this branch. The diff is 30 insertions and 30 deletions across 11 files -- a 1:1 line replacement, which is also the control proving no line-ending rewrite occurred, since a re-encode would have touched every line rather than thirty. No engine behaviour changes. Every replaced line is prose, a comment, or a docstring. Co-Authored-By: Claude Opus 5 --- docs/CONFIGURATION.md | 2 +- docs/PHI.md | 4 ++-- docs/adr/0087-sandbox-subprocess-isolation.md | 2 +- messagefoundry/last_resort.py | 2 +- messagefoundry/logging_setup.py | 4 ++-- messagefoundry/pipeline/_sandbox_worker.py | 2 +- messagefoundry/pipeline/sandbox.py | 16 ++++++++-------- messagefoundry/pipeline/wiring_runner.py | 2 +- tests/test_phi_logging_inventory.py | 6 +++--- tests/test_sandbox.py | 16 ++++++++-------- tests/test_sandbox_worker_logging.py | 4 ++-- 11 files changed, 30 insertions(+), 30 deletions(-) diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index a28a4c64c..5696ba83c 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -856,7 +856,7 @@ now reaps its whole process tree (a Windows kill-on-close job object / a POSIX p a grandchild no longer outlives the kill (BACKLOG #342). That reap is best-effort process hygiene: what makes a stray frame *harmless* is still the codec plus the request-answer binding (a live grandchild can force a respawn, i.e. dead-letter messages on that inbound, but nothing more), not the process teardown. -The child's **stderr is captured by the engine, not inherited** (ADR 0166): a Handler that prints is +The child's **stderr is captured by the engine, not inherited** (ADR 0176): a Handler that prints is relayed into the engine's log attributed to the inbound, the child pid and the worker generation, with **the content itself only at `DEBUG`**. At `INFO` and above you get a rate-limited `WARNING` naming the inbound and counting the lines, and no content — that is deliberate, and it is how the never-log-bodies diff --git a/docs/PHI.md b/docs/PHI.md index 7f8d6cbd2..96a36cefd 100644 --- a/docs/PHI.md +++ b/docs/PHI.md @@ -1037,7 +1037,7 @@ docstrings link here rather than restate it. Two independent mechanisms cover it Router/Handler code, or by a library it pulls, is redacted and CR/LF-scrubbed at the source. Redaction is a property of the **handler**, so this is a second installation of the chain rather than something the child inherits along with a file descriptor. -- **In the engine parent (ADR 0166, BACKLOG #343).** The child is spawned with +- **In the engine parent (ADR 0176, BACKLOG #343).** The child is spawned with `stderr=subprocess.PIPE` — it no longer *inherits* stream 1's sink — and a per-worker drain thread turns those bytes into engine log records attributed to the inbound, the child pid and the worker generation. **Content is relayed at `DEBUG` and only at `DEBUG`.** At `INFO` and above the engine @@ -1055,7 +1055,7 @@ docstrings link here rather than restate it. Two independent mechanisms cover it child's own `DEBUG`/`INFO` records, which the child never emitted. **A byte-cap truncation was rejected, not overlooked:** truncating an HL7 v2 message to its first N bytes keeps MSH and PID and discards the clinically bulky remainder, so it preserves precisely the most identifying part of the - record (ADR 0166). + record (ADR 0176). --- diff --git a/docs/adr/0087-sandbox-subprocess-isolation.md b/docs/adr/0087-sandbox-subprocess-isolation.md index fc482cfbc..bde21c546 100644 --- a/docs/adr/0087-sandbox-subprocess-isolation.md +++ b/docs/adr/0087-sandbox-subprocess-isolation.md @@ -346,7 +346,7 @@ exotic object now reports a *codec* rejection rather than the pickle error text handler-to-handler integrity is false. The boundary drawn here is between admin code and the **engine**. Per-Handler confinement would need a worker per Handler. - **The child's stderr is captured and relayed, no longer inherited** — closed by - [ADR 0166](0166-sandbox-child-stderr-is-captured-and-relayed-with-content-confined-below-info.md) + [ADR 0176](0176-sandbox-child-stderr-is-captured-and-relayed-content-below-info.md) (BACKLOG #343). It was `stderr=None`, so a sandboxed Handler that printed wrote unframed and unattributed straight into the engine's log: a log-injection / PHI-to-log surface, not a frame surface. It is now `stderr=PIPE` drained by a per-worker thread, attributed to the inbound and diff --git a/messagefoundry/last_resort.py b/messagefoundry/last_resort.py index 1fd74d123..4971c6c60 100644 --- a/messagefoundry/last_resort.py +++ b/messagefoundry/last_resort.py @@ -70,7 +70,7 @@ def _thread_excepthook(args: threading.ExceptHookArgs) -> None: The concrete engine threads include **at least** the sandbox session's two per-worker daemon drains — the raw stdout frame reader (``SandboxSession._reader_loop``) and the stderr relay - (``_StderrRelay.run``, ADR 0166) — each of whose ``except`` clauses catches only ``OSError`` by + (``_StderrRelay.run``, ADR 0176) — each of whose ``except`` clauses catches only ``OSError`` by design; anything else escapes ``run()`` and lands here, and the bytes either one was mid-read on are message-derived. Both threads are named for their pipe, their inbound and their worker generation, so ``args.thread.name`` below identifies which one died. ``SystemExit`` is ignored as the diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index 191f30f60..3dbdc00e4 100644 --- a/messagefoundry/logging_setup.py +++ b/messagefoundry/logging_setup.py @@ -113,7 +113,7 @@ def scrub_control_chars(text: str) -> str: record on a configured handler; a caller that assembles a record's content from an untrusted BYTE stream needs it at the point of assembly, because "one peer write is one log record" is that caller's own framing contract and cannot depend on how the host process configured logging — today - the ADR 0166 sandbox stderr relay. Idempotent: the escaped forms contain no control characters.""" + the ADR 0176 sandbox stderr relay. Idempotent: the escaped forms contain no control characters.""" return text.translate(_CTRL_TRANSLATION) @@ -520,7 +520,7 @@ def configure_stderr_logging(level: int = logging.WARNING) -> logging.Handler: redaction here is a property of the **handler**, not of the logger or the call site (see :func:`_install_phi_filters`), so a child that builds its own handler builds an unfiltered one unless it asks for the chain: its records would reach the stderr the parent captures and relays - (ADR 0166) with neither PHI redaction nor CR/LF neutralization (BACKLOG #1054). Every process that + (ADR 0176) with neither PHI redaction nor CR/LF neutralization (BACKLOG #1054). Every process that logs installs the chain, or it does not have it. The text formatter is the shared one, so a child line is byte-compatible with the parent's and diff --git a/messagefoundry/pipeline/_sandbox_worker.py b/messagefoundry/pipeline/_sandbox_worker.py index 9a7aedb41..083c53d7a 100644 --- a/messagefoundry/pipeline/_sandbox_worker.py +++ b/messagefoundry/pipeline/_sandbox_worker.py @@ -25,7 +25,7 @@ answers the call it made. stdout is the binary IPC channel — **nothing else may write to it**, and :func:`_redirect_stdout_to_stderr` -states that intent by pointing ``sys.stdout`` at stderr for the rest of the process (ADR 0166). Logging +states that intent by pointing ``sys.stdout`` at stderr for the rest of the process (ADR 0176). Logging and any diagnostics go to stderr — which the parent CAPTURES and relays, attributed, with content confined below INFO — through the **same PHI-redaction + control-char-scrub filter chain the engine installs on its own handlers** (:func:`~messagefoundry.logging_setup.configure_stderr_logging`), so a diff --git a/messagefoundry/pipeline/sandbox.py b/messagefoundry/pipeline/sandbox.py index 0ddd83c08..28fec622c 100644 --- a/messagefoundry/pipeline/sandbox.py +++ b/messagefoundry/pipeline/sandbox.py @@ -181,7 +181,7 @@ def __repr__(self) -> str: # pragma: no cover - diagnostics only _EOF: Final = _Eof() -# --- child stderr relay (BACKLOG #343, ADR 0166) ------------------------------ +# --- child stderr relay (BACKLOG #343, ADR 0176) ------------------------------ #: One ``read(2)``. The child is spawned with ``bufsize=0``, so ``proc.stderr`` is RAW: this is the #: syscall size, not a buffer fill, and a short read is normal. Sized well above the line cap so a @@ -191,7 +191,7 @@ def __repr__(self) -> str: # pragma: no cover - diagnostics only #: Longest run held while waiting for a newline. A MEMORY bound on the parent, never a redaction: a #: Handler can write megabytes with no terminator, and an unbounded carry lets the child size the #: parent's heap. Reaching it splits one write across several DEBUG records and DISCARDS NOTHING -- -#: which is exactly what distinguishes it from the per-line byte cap ADR 0166 rejected. That cap was +#: which is exactly what distinguishes it from the per-line byte cap ADR 0176 rejected. That cap was #: rejected for a reason specific to this payload: truncating an HL7 v2 message to its first N bytes #: keeps MSH and PID -- the header and the patient identifiers -- and discards the clinically bulky #: remainder, so it preserves precisely the most identifying part of the record. It is the worst @@ -209,7 +209,7 @@ def __repr__(self) -> str: # pragma: no cover - diagnostics only class _StderrRelay: - """One worker GENERATION's stderr, turned into log records (BACKLOG #343, ADR 0166). + """One worker GENERATION's stderr, turned into log records (BACKLOG #343, ADR 0176). Content at DEBUG and only DEBUG; at INFO and above an attributed, rate-limited notice carrying identity and a COUNT and no content. CLAUDE.md section 9 holds here **by construction** rather than @@ -329,7 +329,7 @@ def _notice(self, *, force: bool) -> None: self._last_notice = now log.warning( "sandbox worker wrote to stderr [%s pid %d gen %d]: %d line(s) since the last notice, " - "%d total for this worker; content is relayed at DEBUG only (ADR 0166)", + "%d total for this worker; content is relayed at DEBUG only (ADR 0176)", self._inbound, self._pid, self._gen, @@ -562,7 +562,7 @@ def __init__( ) -> None: self.policy = policy # Required, with no default, deliberately: this is what attributes a relayed stderr line to a - # feed (ADR 0166), and a default would silently reinstate the unattributable relay for every + # feed (ADR 0176), and a default would silently reinstate the unattributable relay for every # future caller. Parent-side only -- it is not marshalled, on the same rule as ``_env`` below. self._inbound = inbound self._config_dir = str(Path(config_dir)) @@ -617,7 +617,7 @@ def _spawn(self) -> None: [sys.executable, "-m", WORKER_MODULE], stdin=subprocess.PIPE, stdout=subprocess.PIPE, - # CAPTURED, not inherited (BACKLOG #343, ADR 0166): with ``stderr=None`` the child's stderr + # CAPTURED, not inherited (BACKLOG #343, ADR 0176): with ``stderr=None`` the child's stderr # WAS the engine's, so admin-authored Handler code wrote unframed, unattributed bytes -- # including whole message bodies -- straight into the operator's log of record. stderr=subprocess.PIPE, @@ -761,7 +761,7 @@ def _reject_unsolicited(self, proc: subprocess.Popen[bytes] | None, when: str) - with the rest of the worker's tree, so it cannot keep writing to the pipe. **The justification is the protocol violation, NOT a claim that fd 1 is unreachable.** An - earlier version of this docstring said the ADR 0166 stdout rebind meant "the text layer cannot + earlier version of this docstring said the ADR 0176 stdout rebind meant "the text layer cannot reach fd 1 at all", so "there is no benign case to preserve". **Both were false, and this docstring is where a DESTRUCTIVE action is reasoned from, which is what made it worth correcting rather than softening.** Rebinding the *name* ``sys.stdout`` leaves the descriptor @@ -769,7 +769,7 @@ def _reject_unsolicited(self, proc: subprocess.Popen[bytes] | None, when: str) - ``BufferedWriter`` :func:`_sandbox_worker.main` captured as the frame writer — and ``os.write(1, ...)`` and ``open(1, "wb")`` reach it too. What the rebind actually removes is the *accidental* case (a bare ``print()`` in a Handler), which is worth having and is all it - claims in ADR 0166 and in the worker's own bootstrap comment; asserting more here contradicted + claims in ADR 0176 and in the worker's own bootstrap comment; asserting more here contradicted both, in the same change that wrote them. The action is unchanged and does not need the stronger claim: a frame no outstanding request diff --git a/messagefoundry/pipeline/wiring_runner.py b/messagefoundry/pipeline/wiring_runner.py index 36a2481ca..005a20ea5 100644 --- a/messagefoundry/pipeline/wiring_runner.py +++ b/messagefoundry/pipeline/wiring_runner.py @@ -2623,7 +2623,7 @@ def _sandbox_for(self, name: str) -> SandboxSession | None: # so the child serves exactly what mode=off would rather than its own re-read of codesets/. session = SandboxSession( policy, - inbound=name, # attributes the child's relayed stderr to this feed (ADR 0166) + inbound=name, # attributes the child's relayed stderr to this feed (ADR 0176) config_dir=cfg_dir, env=env, code_sets=self.registry.code_sets, diff --git a/tests/test_phi_logging_inventory.py b/tests/test_phi_logging_inventory.py index 4964935fc..5dff2ee23 100644 --- a/tests/test_phi_logging_inventory.py +++ b/tests/test_phi_logging_inventory.py @@ -679,7 +679,7 @@ def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: stream 1's own sink outside the chain, and §7 disclosed that. It now calls ``configure_stderr_logging``, which installs the same three filters (BACKLOG #1054), so the disclosure must be gone instead. In the PARENT: the child's stderr is no longer *inherited* at all - (ADR 0166) — it is captured and relayed, with content gated below INFO — so §7's claim now rests on + (ADR 0176) — it is captured and relayed, with content gated below INFO — so §7's claim now rests on that gate too, and the gate is pinned here rather than only described in prose. Pinned BOTH ways, because the interesting direction is the regression: a future edit that put @@ -693,7 +693,7 @@ def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: sandbox = (_ROOT / "messagefoundry" / "pipeline" / "sandbox.py").read_text(encoding="utf-8") assert "stderr=subprocess.PIPE" in sandbox, ( "the child's stderr is no longer captured by the parent — it is inherited raw again, so §7's " - "'content only at DEBUG' gate does not exist. Revisit §7 and ADR 0166." + "'content only at DEBUG' gate does not exist. Revisit §7 and ADR 0176." ) assert "isEnabledFor(logging.DEBUG)" in sandbox, ( "the stderr relay no longer gates content on DEBUG. §7 claims the never-log-bodies rule holds " @@ -706,7 +706,7 @@ def test_the_sandbox_worker_stderr_writer_is_filtered_not_disclosed() -> None: assert disclosed, ( "the sandbox worker child emits through a bare basicConfig, whose handler carries no " "filters, so §7's 'three filters on every record' claim is not true at the source. The " - "parent's ADR 0166 relay does not cover this: relayed records ride the engine's handlers, " + "parent's ADR 0176 relay does not cover this: relayed records ride the engine's handlers, " "but a record the CHILD writes unredacted is already unredacted on the wire. Say so." ) assert "in the engine process" in text, ( diff --git a/tests/test_sandbox.py b/tests/test_sandbox.py index e1173f94f..9bb27ea42 100644 --- a/tests/test_sandbox.py +++ b/tests/test_sandbox.py @@ -449,7 +449,7 @@ def test_run_context_codec_snapshots_mappingproxy_views() -> None: def _session(config_dir: str, inbound: str = "IB_T", **kw: object) -> SandboxSession: # The default lives in this TEST helper only, never in the production constructor, where a default - # would silently reinstate the unattributable relay ADR 0166 exists to close. + # would silently reinstate the unattributable relay ADR 0176 exists to close. return SandboxSession( SandboxPolicy(mode=SandboxMode.SUBPROCESS, wall_seconds=15.0), inbound=inbound, @@ -1113,7 +1113,7 @@ def test_worker_kill_reaps_the_whole_process_tree(tmp_path: Path) -> None: # --- (e) child stderr is captured and relayed, content confined below INFO ----- -# BACKLOG #343 / ADR 0166. Two problems share one root: (a) a sandboxed Handler's line was +# BACKLOG #343 / ADR 0176. Two problems share one root: (a) a sandboxed Handler's line was # byte-indistinguishable from an engine line, and (b) a Handler that printed a message body wrote a # full payload into the general log. (b) is the one CLAUDE.md section 9 forbids, and the tests below # pin the property that closes it BY CONSTRUCTION: no call site above DEBUG carries child content. @@ -1134,7 +1134,7 @@ def r_err(msg): @handler("h_body") def h_body(msg): - # ADR 0166 (b): a Handler writing a full message body to stderr. Synthetic HL7 only. + # ADR 0176 (b): a Handler writing a full message body to stderr. Synthetic HL7 only. print(str(msg), file=sys.stderr) return Send("OB_ERR", "OK") @@ -1158,7 +1158,7 @@ def h_raw_stdout(msg): """ #: Writes 1 MiB to stderr at MODULE scope, i.e. inside ``load_config()`` -- before the child can write -#: its boot reply. This is the deadlock ADR 0166 says the decision CREATES: a PIPE nobody drains blocks +#: its boot reply. This is the deadlock ADR 0176 says the decision CREATES: a PIPE nobody drains blocks #: its writer once the OS buffer fills (order 64 KiB). _FLOOD_GRAPH = """ import sys @@ -1283,7 +1283,7 @@ def test_at_debug_content_is_relayed_attributed_and_control_scrubbed( def test_a_raw_write_to_fd_1_cannot_forge_a_frame_because_stdout_is_rebound( tmp_path: Path, ) -> None: - """ADR 0166 D3, the adjacent defect closed with the same fd discipline. + """ADR 0176 D3, the adjacent defect closed with the same fd discipline. The Handler writes a COMPLETE forged frame through ``sys.stdout.buffer``. With the bootstrap rebind ``sys.stdout`` is stderr, so those bytes go to fd 2 and the dispatch answers normally. Without it @@ -1314,7 +1314,7 @@ def test_a_bootstrap_stderr_flood_does_not_wedge_the_spawn(tmp_path: Path) -> No NOT below the boot-frame WRITE, which is what this said first and is measurably wrong: starting the drain immediately after the write does NOT wedge, because the parent then blocks on the reply - while the drain is already running (ADR 0166 records the measurement). A falsification that does + while the drain is already running (ADR 0176 records the measurement). A falsification that does not falsify is worse than none -- it reads as a checked escape hatch, and the one person who follows it concludes the guard is untestable rather than that the instruction was wrong.""" (tmp_path / "graph.py").write_text(_FLOOD_GRAPH, encoding="utf-8") @@ -1334,7 +1334,7 @@ def test_a_bootstrap_stderr_flood_does_not_wedge_the_spawn(tmp_path: Path) -> No def test_the_relay_thread_ends_when_the_worker_tree_is_reaped(tmp_path: Path) -> None: - """A second drain thread is a second teardown obligation (ADR 0166), and it is EOF-driven. + """A second drain thread is a second teardown obligation (ADR 0176), and it is EOF-driven. Reuses the orphan graph so a GRANDCHILD also holds fd 2 -- which is the case the EOF argument actually rests on, since the immediate worker dying is not enough to close a pipe another process @@ -1437,7 +1437,7 @@ def test_the_line_cap_bounds_a_record_without_discarding_a_byte( caplog: pytest.LogCaptureFixture, ) -> None: """The cap is a MEMORY bound on the parent, never a redaction -- which is what distinguishes it - from the per-line byte cap ADR 0166 rejected. Reaching it splits one write across several records + from the per-line byte cap ADR 0176 rejected. Reaching it splits one write across several records and discards nothing. (The rejected cap would have kept MSH and PID and thrown the rest away: the worst available redaction for an HL7 v2 payload, since that is precisely the identifying part.)""" caplog.set_level(logging.DEBUG) diff --git a/tests/test_sandbox_worker_logging.py b/tests/test_sandbox_worker_logging.py index af8683f30..fd9bdae50 100644 --- a/tests/test_sandbox_worker_logging.py +++ b/tests/test_sandbox_worker_logging.py @@ -58,7 +58,7 @@ def test_sandbox_worker_child_logs_redacted_and_scrubbed_to_stderr() -> None: def test_the_stdout_rebind_sits_between_the_frame_capture_and_the_boot_read() -> None: - """ADR 0166 D3 is a SOURCE-ORDER property, so it needs a source-order instrument (SDS-3.8). + """ADR 0176 D3 is a SOURCE-ORDER property, so it needs a source-order instrument (SDS-3.8). ``_redirect_stdout_to_stderr()`` must run AFTER ``main`` captures ``sys.stdout.buffer`` -- at module scope that capture would resolve to fd 2 and every MFW2 frame would go to the wrong pipe -- and @@ -106,6 +106,6 @@ def _call_line(name: str) -> int: boot_read = _call_line("_read_frame_bytes") assert capture < rebind < boot_read, ( "the fd-1 capture / stdout rebind / boot-frame read are out of order in main(): the rebind " - f"must follow the capture and precede the first untrusted code, ADR 0166 D3 " + f"must follow the capture and precede the first untrusted code, ADR 0176 D3 " f"(capture line {capture}, rebind {rebind}, boot read {boot_read})" )