Skip to content

fix(store): give the off-box audit tee a sink when the process configured none (BACKLOG #1199) - #820

Merged
wshallwshall merged 1 commit into
mainfrom
worktree-agent-afdb9bf55204dacce
Sep 4, 2026
Merged

fix(store): give the off-box audit tee a sink when the process configured none (BACKLOG #1199)#820
wshallwshall merged 1 commit into
mainfrom
worktree-agent-afdb9bf55204dacce

Conversation

@wshallwshall

Copy link
Copy Markdown
Collaborator

Closes the tee prerequisite named in BACKLOG #1199. It does not move the ASVS 16.4.3 cell to pass, and nothing here claims it does.

The defect

messagefoundry installs a root log handler in exactly two places: the serve and supervise subcommands. Every other subcommand runs with an empty root handler list, and logging.lastResort is WARNING-only, so the off-box audit tee's INFO record was dropped outright rather than degraded.

The measured instance is messagefoundry backup. BackupRunner._record_success and BackupRunner._record_failure both write a dr_backup audit row from exactly such a process, so on a first deployment their off-box copy would be produced and silently discarded in every configuration. That is the module's own off-box guarantee failing without a symptom.

The failing tests, written first

Two guards drive the real subcommand in a real child process. Both were red before the fix, with a positive control in each so an empty result could not be mistaken for a clean one.

Guard Before the fix Positive control
..._ships_its_success_audit_row_off_box stderr empty, no audit record exit 0 and the archive exists on disk, so the row really was written
..._ships_its_failure_audit_row_off_box no audit record ALERT backup_failed did reach stderr from that same handler-less process

The second control is the discriminating one: a WARNING on the same process reached stderr through logging.lastResort while the tee's INFO record did not, so the stream demonstrably worked and the record was dropped by level, not by a dead process.

Six of the eight new guards were confirmed red before the fix. The other two pass in both states by design: one pins that the handler-less shape the rest are built on is the measured one, the other is the no-regression guard that a configured process still gets exactly one copy.

The fix

emit_audit_tee now calls logging_setup.ensure_logger_sink. It takes its own handler off the logger, then asks logging.Logger.hasHandlers whether anything else would receive the record. That predicate is not an approximation: read from the interpreter's source, it walks the chain with the same stop condition callHandlers uses, so it is true exactly when callHandlers would find at least one handler. On false it installs a named stderr handler built by the new shared logging_setup.build_stderr_handler, and takes it back off the moment the process configures a sink, so serve and supervise are untouched and nothing double-emits.

The redaction chain is identical, not merely equivalent. The fallback is built by the same helper the configured stderr sink uses, so the chain is shared by construction rather than by a second copy. Verified byte-for-byte: for a PHI-bearing detail, the fallback's rendering equals what configure_logging's stdout handler emits. Nothing was weakened, reordered or bypassed.

Stderr rather than stdout is a requirement, not a preference: subcommands print a machine-readable payload to stdout under --json, and a log line there would corrupt the document a caller parses.

Scope, and what was deliberately not done

Per the owner ruling of 2026-09-03 this is one slice. Not built here, and still open on #1199: the durable forwarder (queue handler, reconnect loop, on-disk spool), the verb-shaped start gate, the collector-separation probe, supervisor-process forwarding, the sandbox-child off-box path, the at_capacity log line, off-box tees for connection_event / message_events / alert_instance / response, the tray-log disposition, the forwarder egress allowlist, and posture reporting.

Also deliberately avoided, each a recorded wrong move for this cell: no edit to docs/DEPLOYMENT.md (a runbook edit bought this cell a Pass in 2026-07 and lost it two days later), no flip of forward_protocol to TLS while the collector host stays unset, and no crediting of forward_hop_attested.

Per the coordinator's steer, the three store backends' record_audit are untouched, so this does not overlap PR 764. Fixing it at the tee covers all three call sites at once. logging_setup.py is not in that PR's file list either. Every reference here is anchored on a symbol rather than a line number, for the same reason.

Two adjacent defects found, not fixed here

Both are recorded in the #1199 row, named as subjects rather than numbers.

  1. The double-redacted tee line loses its JSON framing. The handler-level RedactionFilter re-scrubs the already-safe_text'd line, reads PID| inside the rendered JSON as a segment run, and cuts to end-of-line, so an audit record whose detail carries an HL7 fragment reaches the wire with its closing brace gone. Measured as byte-identical on the configured stdout path and on the new fallback, so it is pre-existing and belongs to the redaction chain rather than to this change. It errs toward more redaction, never less.
  2. logging.lastResort is unfiltered. Measured in a bare interpreter: it carries filters=[] and formatter=None, and a WARNING carrying a synthetic PID segment printed verbatim. So in those handler-less subcommand processes, WARNING-level traffic would bypass the PHI chain on a first deployment. Closing that means configuring logging for every subcommand in main(), which is outside this ruling's scope and needs its own item.

Checks run

  • ruff check . and ruff format --check . — pass
  • mypy messagefoundry (strict) — pass, 267 source files. Run by hand, since pre-commit does not run it.
  • pytest on the affected areas — 207 pass across test_audit_offbox_tee, test_logging, test_logging_surfaces, test_audit_integrity, test_cli_backup_dispatch, test_hop_refusal_log_forwarding, test_dependency_boundaries, test_sandbox_import_boundary, test_sandbox_worker_logging, test_phi_logging_inventory, test_redaction
  • Ledger and docs gates — backlog_status_check (657 items, each one status), ledger_check, licence_header_check, control_char_check all pass
  • All pre-commit hooks passed at commit time, including forbidden-content, gitleaks and bandit
  • /simplify run before committing; findings applied are described below

Not read by me: the full pytest suite was still running when this branch was pushed, and any hosted-runner-only leg (for example windows-service-smoke under NSSM) never reports before a Builder's process exits. Those need reading on this PR.

What /simplify changed

Applied: replaced a hand-rolled propagation walk with logging.Logger.hasHandlers, which also removed a latent asymmetry where a same-named handler on a parent logger would have been found but never removed; moved the mechanism from store/audit_tee.py into logging_setup.py beside the other process-sink patterns, so the four remaining off-box tees cost one line each; renamed the handler tag away from "last resort" so it cannot be confused with the messagefoundry.last_resort logger or logging.lastResort; stated the defect once instead of five times; simplified the test fixture and tightened the subprocess timeout from 300s to 120s.

Skipped, with reasons: importing the backup fixtures from test_cli_backup_dispatch.py would need a parameter added to a test module outside this diff, and the remaining scaffolding is six trivial lines that the exit-code control already guards; dropping the success-path subprocess test would drop half the measured instance; the filter-chain test is kept because it states the identical-chain requirement directly and fails with a precise diagnosis; a 0.069 microsecond micro-optimisation was declined against a 48.6 microsecond emit, on the reviewer's own recommendation.

🤖 Generated with Claude Code

…ured none (BACKLOG #1199)

The tee ends in a logger call, and only two call sites in the package install a
root handler: the serve and supervise subcommands. Every other subcommand runs
with an empty root handler list, and logging.lastResort is WARNING-only, so the
tee's INFO record was dropped outright rather than degraded.

Measured on the real backup subcommand in a child process: it returned 0 with
the archive on disk and an EMPTY stderr, while on the failure arm its ALERT
backup_failed WARNING reached stderr from that same handler-less process and the
audit record did not. That WARNING is the discriminating control -- the stream
worked and the record was dropped by level. So on a first deployment the
dr_backup success and failure rows would produce an off-box copy that is
silently discarded in every configuration.

logging_setup.ensure_logger_sink takes its own handler off the logger, asks
logging.Logger.hasHandlers whether anything else would receive the record, and
on false installs a named stderr handler built by the new shared
build_stderr_handler. The redaction chain is therefore identical to the
configured path's by construction, verified byte-for-byte against what
configure_logging's stdout handler emits for a PHI-bearing detail. The handler
comes back off the moment the process configures a sink, so serve and supervise
are untouched and nothing double-emits. Stderr rather than stdout, because
subcommands print a machine-readable payload to stdout under --json.

The mechanism sits in logging_setup beside the two shipped answers to "how does
this process get a sink", so the four remaining off-box tees #1199 lists cost
one line each. The three store backends' record_audit are untouched: the defect
is the tee's, and fixing it there covers all three call sites at once.

This stops evidence being dropped inside the box. It transmits nothing off the
host, and the ASVS 16.4.3 cell does not reach pass -- the durable forwarder, the
verb-shaped start gate and the rest of that programme stay open on #1199.

Eight guards in tests/test_audit_offbox_tee.py. Six were confirmed red before
the fix; the other two pass in both states by design -- one pins the
handler-less shape the rest are built on, the other is the no-regression guard
that a configured process still gets exactly one copy.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

LANDER: applying reviewed under an explicit owner override. The owner has suspended the reviewer process and directed that this label be applied as needed to clear the gate.

SO READ THIS LABEL AS A BYPASS TOKEN, NOT A REVIEW. It records that the gate was cleared by instruction. It does not assert that anyone read this diff, and no later reader should infer one from it.

What I can say: this PR appeared in a read-only pre-verification sweep of all 59 non-draft open PRs (per-PR defect read, plus pairwise git merge-tree against every PR sharing a non-BACKLOG file), and no blocking defect was recorded against it. That sweep did not run any tests, and CI has been down for hours, so nothing here has a current green.

-- Lander

@wshallwshall wshallwshall added reviewed A reviewer has read this. Removed automatically when new commits arrive. and removed reviewed A reviewer has read this. Removed automatically when new commits arrive. labels Sep 4, 2026
@wshallwshall
wshallwshall added this pull request to the merge queue Sep 4, 2026
Merged via the queue into main with commit 99887f5 Sep 4, 2026
51 of 79 checks passed
@wshallwshall
wshallwshall deleted the worktree-agent-afdb9bf55204dacce branch September 4, 2026 19:44
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

reviewed A reviewer has read this. Removed automatically when new commits arrive.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant