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

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: wshallwshall <mefordev@messagefoundry.org>
Co-authored-by: Claude Opus 5 <noreply@anthropic.com>

Author: 3 people

docs/BACKLOG.md

@@ -11308,6 +11308,7 @@ Nothing here touches the TLS/FTPS context in the same module, which was already
 
 > 🔢 **Re-scored 2026-08-20 -> P2.** Value **6/10** · Difficulty **5/10** · _quick win_. Shipped defaults are unchanged: forward_host is None at settings.py:1413, the handler installs only behind if forward is not None at logging_setup.py:438, and the protocol default at :1415 is UDP. Value 6 not 7: the engine ships the entire secure-transmission mechanism (SyslogForward at logging_setup.py:240 with native TLS at :300, CA anchoring and hostname verification, plus the REFUSE gate at settings.py:2475), so an operator reaches a conforming posture by setting a host and forward_protocol=tls -- awkward, but a real workaround, which is what rung 7 requires to be absent. Difficulty 5 for measuring the REFUSE gate's actual coverage, arguing the deployed-system-versus-product reading against the text, and weighing a TLS protocol default against a precedent that a runbook edit bought and lost this cell in two days. _(was 7/10 · 5/10.)_
 > Research: done 2026-08-20
+> 🚧 **One slice BUILT 2026-09-03 -- the tee's per-process handler dependency, which the research named as the prerequisite for every other subject in this programme and as the thing that falsifies the one detection-limb row graded verified.** `emit_audit_tee` now guarantees its record reaches a handler in a process that installed none, so the `backup` subcommand's success and failure `dr_backup` rows no longer produce an off-box copy that is discarded unread. **The cell does NOT reach pass and nothing in this change claims it does:** this stops evidence being dropped INSIDE the box; it still transmits nothing OFF the host. Everything else in the programme stays open -- see "Built 2026-09-03" at the end of this item for the list.
 >
 > **Filed 2026-08-08 - not started. RESEARCH item: the goal is an HONEST pass, and "cannot honestly reach pass" is a valid finding.** ASVS **16.4.3** (L2) currently scores **partial**. The pinned verb requires logs to be securely transmitted to a logically separate system so they survive a breach of the application. What holds it short is that no shipped default transmits anything: `forward_host` is None (`config/settings.py:1359`) and `configure_logging` installs stdout only behind `if forward is not None` (`logging_setup.py:437`).
 > Verdict: research
@@ -11338,6 +11339,67 @@ Nothing here touches the TLS/FTPS context in the same module, which was already
 
 **Proposed work, unallocated and by subject:** the durable off-box forwarder; the verb-shaped start gate; a collector-separation probe that refuses when every resolved address is an address of the engine host; supervisor-process forwarding; the sandbox-child off-box path and the inventory wording that hides it; the `at_capacity` log line; the tee's per-process handler dependency, which must be fixed before any new tee is built; off-box tees for the remaining event tables, including the alert-instance and response tables the first plan named only in part; a disposition for the tray log, argued on security-log-content grounds rather than the PHI-content grounds an existing exclusion actually uses; the never-built forwarder egress allowlist; posture reporting for the absence of forwarding and for hop attestation (measured: zero forwarder references in `messagefoundry/checks.py` and `messagefoundry/verify/` against a positive control of forty-one advisory tokens, and zero occurrences inside the loosening registry body against a positive control of three hits for another loosening); and a subject ruling on whether the extension's output channels are logging components for this verb -- noting the falsifier published for the out-of-subject reading, an extension-side event with no engine-side counterpart, is arguably already tripped by the connectivity-failure outcomes at `ide/src/engineLog.ts:63-65`.
 
+**Built 2026-09-03 -- the tee's per-process handler dependency, and ONLY that.** The research's
+measurement reproduced exactly: `grep -rn "configure_logging(\|configure_stderr_logging(\|basicConfig("`
+over the package returns two handler-installing call sites, `serve` and `supervise` in
+`messagefoundry/__main__.py`, against a positive control of 111 `getLogger(` hits and a negative
+control returning zero. In a bare interpreter the tee's INFO record produced NOTHING while a WARNING
+on the same logger printed and the root handler list was empty, because `logging.lastResort` is
+WARNING-only. Driven from the measured instance rather than a unit stub: the real `messagefoundry
+backup` subcommand, run in a CHILD process, returned 0 with the archive on disk and an EMPTY stderr;
+on the failure arm its `ALERT backup_failed` WARNING reached stderr from the same handler-less process
+while the tee's record did not, which is the discriminating control -- the stream demonstrably worked
+and the record was dropped by level, not by a dead process.
+
+**The fix.** `emit_audit_tee` now calls `logging_setup.ensure_logger_sink`, which takes its own
+handler off the logger and then asks `logging.Logger.hasHandlers` -- the standard library's own walk,
+the same stop condition `callHandlers` uses, read from the interpreter's source rather than assumed --
+whether anything else would receive the record. On false it installs a named stderr handler built by
+the new shared `logging_setup.build_stderr_handler`, so the redaction chain is IDENTICAL to the
+configured path's by construction rather than by a second copy that could drift. It comes back off
+the moment the process configures a sink, so `serve` and `supervise` are untouched and nothing
+double-emits. Verified byte-for-byte: for a PHI-bearing `detail` the fallback's rendering equals what
+`configure_logging`'s stdout handler emits. Stderr rather than stdout is a requirement, not a
+preference -- subcommands print a machine-readable payload to stdout under `--json`. Eight guards in
+`tests/test_audit_offbox_tee.py`; SIX were confirmed RED before the fix, and the other two pass in
+both states by design -- one asserts 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 mechanism sits in `logging_setup`, not in the tee**, beside the two shipped answers to "how
+does this process get a sink" -- entry-point configuration and import-time remediation -- and the
+`silence_phi_prone_dependency_loggers` precedent, so the four remaining off-box tees this item still
+lists cost one line each rather than a copied function. It has exactly one caller today. The three
+store backends' `record_audit` were deliberately not touched: the defect is the tee's, and fixing it
+at the tee fixes all three call sites at once.
+
+**Two adjacent defects found, deliberately NOT fixed, and unfiled.** Named as subjects, not numbered,
+per the citation rule.
+
+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, and a SIEM parsing one object per line gets a parse error
+   instead of the record. Measured 2026-09-03 as byte-identical on the CONFIGURED stdout path and on
+   the new fallback, so it is pre-existing, belongs to the redaction chain rather than to this
+   change, and errs toward MORE redaction rather than less.
+2. *`logging.lastResort` is unfiltered, so the WARNING traffic of every handler-less subcommand
+   bypasses the PHI chain.* Measured 2026-09-03 in a bare interpreter: `logging.lastResort` carries
+   `filters=[]` and `formatter=None`, and a WARNING carrying a synthetic `PID` segment printed
+   VERBATIM. This change closes the INFO record; it does not touch that, and closing it means
+   configuring logging for every subcommand in `main()`, which is the scope the 2026-09-03 ruling
+   excluded. Same family as the sandbox child's unfiltered-handler defect that
+   `configure_stderr_logging` was built for.
+
+**Still open, and this item stays open for them:** the durable off-box forwarder (queue handler,
+reconnect loop, bounded on-disk spool); the verb-shaped start gate; the collector-separation probe;
+supervisor-process forwarding; the sandbox-child off-box path and the inventory wording that hides it;
+the `at_capacity` log line; off-box tees for `connection_event`, `message_events`, `alert_instance`
+and `response`; the tray-log disposition; the never-built forwarder egress allowlist; posture
+reporting for the absence of forwarding and for hop attestation; and the extension-output-channel
+subject ruling. **Nothing under `docs/DEPLOYMENT.md` was touched** -- the runbook purchase is this
+cell's recorded wrong move, and it was reversed in two days once already -- `forward_protocol` was not
+flipped while the collector host stays unset, and `forward_hop_attested` was not credited anywhere.
+
 ## 1202. the vault ASVS gate runs a verifier this repo owns, on a bare interpreter, and nothing here checked it would run
 
 > ✅ **SHIPPED 2026-08-09, banner corrected 2026-08-21 -- the item said "FIXED in the same change" while its banner read open, so it contradicted its own body for twelve days.** Closed on verification against code, not against the scoring pass: `scripts/asvs/scorecard.py` is present at the literal path both vault workflows hardcode, and `tests/test_asvs_verifier_vault_contract.py` carries all four limbs by name -- `test_the_verifier_is_at_the_path_the_vault_hardcodes`, `test_a_mirrored_tool_imports_only_the_standard_library` (parametrized, ast-based so it sees DEFERRED imports), `test_the_verifier_runs_as_a_bare_script_with_nothing_installed`, and `test_the_scanner_reds_on_a_contract_violation` -- the last being the negative control that proves the detector can fail.

messagefoundry/logging_setup.py

@@ -39,8 +39,10 @@
 from messagefoundry.redaction import redact
 
 __all__ = [
+    "build_stderr_handler",
     "configure_logging",
     "configure_stderr_logging",
+    "ensure_logger_sink",
     "set_runtime_level",
     "current_log_level",
     "silence_phi_prone_dependency_loggers",
@@ -509,30 +511,115 @@ def configure_logging(
     return forwarder_installed
 
 
+def build_stderr_handler() -> logging.Handler:
+    """A **stderr** handler carrying the shared text formatter and the PHI-redaction + control-char-
+    scrub filter chain — the single definition of "a MessageFoundry log sink on stderr".
+
+    Redaction here is a property of the **handler**, not of the logger or the call site (see
+    :func:`_install_phi_filters`), so anything that builds its own stderr handler builds an
+    *unfiltered* one unless it asks for the chain. At least two callers need one:
+    :func:`configure_stderr_logging`, for a process whose stdout is a binary channel, and
+    :func:`ensure_logger_sink`, for a process that installed no handler at all. Stating the chain
+    once means they cannot drift apart.
+
+    The handler level is left at ``NOTSET`` — matching the handlers :func:`configure_logging`
+    installs, so a record's only level gate is its logger's. ``sys.stderr`` is bound at build time,
+    exactly as :func:`configure_logging` binds ``sys.stdout``.
+    """
+    handler = logging.StreamHandler(sys.stderr)
+    handler.setFormatter(_make_formatter("text"))
+    _install_phi_filters(handler)
+    return handler
+
+
+def _fallback_sink_name(logger: logging.Logger) -> str:
+    """The handler name :func:`ensure_logger_sink` tags its own sink with, derived from ``logger``.
+
+    Deliberately **not** spelled "last resort", though that is what it is: this package already has a
+    ``messagefoundry.last_resort`` logger for excepthook reporting, and the standard library has
+    ``logging.lastResort``. Three unrelated things under one grep is the adjacent-name confusion
+    CLAUDE.md §11 keeps apart by rule.
+    """
+    return f"{logger.name}.fallback-sink"
+
+
+def ensure_logger_sink(logger: logging.Logger) -> None:
+    """Guarantee the next record on ``logger`` reaches a handler, in a process that configured none
+    (BACKLOG #1199). Idempotent, and self-removing once the process configures a real sink.
+
+    **The defect this closes.** Only two call sites in the package install a root handler — the
+    ``serve`` and ``supervise`` subcommands, both in :mod:`messagefoundry.__main__`. Every other
+    subcommand runs with an EMPTY root handler list, and ``logging.lastResort`` is WARNING-only, so
+    an INFO record is dropped outright rather than degraded. The measured instance is the off-box
+    audit tee (:mod:`messagefoundry.store.audit_tee`), whose whole purpose is that a copy of every
+    audit record leaves the box.
+
+    **What it does.** Takes our own handler off ``logger``, then asks ``logging.Logger.hasHandlers``
+    whether anything else would receive the record. That predicate is not an approximation of the
+    question: checked against the interpreter's source, it walks the chain — own handlers, then each
+    parent while ``propagate`` holds — with the SAME stop condition ``callHandlers`` uses, so it is
+    true exactly when ``callHandlers`` would find at least one handler, which is the condition that
+    decides whether the standard library diverts to its last resort. Handler LEVEL is deliberately
+    not consulted, for the same reason ``callHandlers`` does not consult it in that count: the
+    question is whether the process configured a sink at all, not whether that sink chose to keep
+    this record. On false, put ours back — the standard library's idea, at ``NOTSET`` instead of
+    WARNING and carrying the PHI filter chain. On true, ours simply stays off.
+
+    Removing first is what lets the standard library answer the question — ``hasHandlers`` cannot be
+    told to ignore one handler — and the removed object goes straight back rather than being rebuilt,
+    so a handler-less process builds one handler for its lifetime, not one per call.
+
+    **Lazy and per-call, unlike the two shipped patterns**, which are entry-point configuration
+    (``pipeline/_sandbox_worker``) and import-time remediation (``parsing/__init__``). Neither works
+    here: :func:`configure_logging` clears the **root** logger's handlers and never touches a named
+    one, so a sink installed once at import or at an entry point would survive into ``serve`` and
+    double-emit for the life of the service. Re-checking is what makes self-removal possible.
+
+    **Stderr, not stdout**, and that is a requirement rather than a preference: subcommands print a
+    machine-readable payload to stdout under ``--json``, and a log line there would corrupt the
+    document a caller parses.
+
+    **Not a forwarder.** This puts the record in front of an operator and into whatever the service
+    manager captures; it does not transmit anything off the host. The durable off-box forwarder, and
+    the question of what ASVS 16.4.3 requires beyond it, stay open on BACKLOG #1199.
+
+    Costs nothing on a configured process: it takes the ``hasHandlers`` branch and builds nothing, so
+    no new work lands on the event-loop thread a caller may be running on.
+    """
+    name = _fallback_sink_name(logger)
+    ours = [h for h in logger.handlers if h.name == name]
+    for handler in ours:
+        logger.removeHandler(handler)
+    if logger.hasHandlers():
+        return
+    if ours:
+        logger.addHandler(ours[0])
+        return
+    # Unsynchronized on purpose. Two threads racing here both install, and the loser's handler is
+    # dropped on the next call — so the worst case is ONE duplicated line, never a dropped one, and it
+    # self-heals. A lock on every call would buy nothing against that, and the shipped processes that
+    # reach this branch (the CLI subcommands) are single-threaded anyway.
+    handler = build_stderr_handler()
+    handler.set_name(name)
+    logger.addHandler(handler)
+
+
 def configure_stderr_logging(level: int = logging.WARNING) -> logging.Handler:
     """Install a **stderr-only** root handler carrying the same PHI-redaction + control-char-scrub
     filter chain :func:`configure_logging` puts on stdout, and return it.
 
     For a MessageFoundry child process whose **stdout is a binary channel**: today the ADR 0087 sandbox
     worker, whose stdout carries the MFW2 IPC frames, so a stray log byte written there would corrupt a
     frame. The obvious way to express that — ``logging.basicConfig(stream=sys.stderr)`` — gets the
-    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 stderr the parent captures and relays
-    (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
-    :class:`ControlCharScrubFilter`'s "no line may impersonate the record prefix" guarantee is stated
-    against the same prefix on both streams.
+    stream right and the *filters* wrong: it installs a handler with **no filters at all**, so a
+    child's records would reach the stderr the parent captures and relays (ADR 0176) with neither PHI
+    redaction nor CR/LF neutralization (BACKLOG #1054). :func:`build_stderr_handler` is what supplies
+    the chain and the shared text formatter here, and says why that has to be asked for.
 
     Replaces any handlers already on the root logger, exactly as :func:`configure_logging` does, so it
     is idempotent and safe to call from a test.
     """
-    handler = logging.StreamHandler(sys.stderr)
-    handler.setFormatter(_make_formatter("text"))
-    _install_phi_filters(handler)
+    handler = build_stderr_handler()
 
     root = logging.getLogger()
     for existing in list(root.handlers):