fix(cli): a --json payload no longer shares stdout with the log (BACKLOG #1489)

docs/BACKLOG.md

@@ -27824,7 +27824,13 @@ connection-scaling guard.
 
 ## 1489. the log write guard prints its roll notice to stdout, so it lands inside captured CLI output and breaks --json readers
 
-> 🔢 **Filed 2026-09-08 -- not started.** `messagefoundry/logging_guard.py` (shipped by PR #883 at 07:24Z, commit `995fc2790`) writes `application log sink stdout was rolled after a write` to the **stdout sink**. A CLI command invoked with `--json` writes its payload to that same stream, so a reader doing `json.loads(...)` sees the notice first and raises `Extra data: line 1 column 5`. Six tests in `tests/test_checks.py` fail this way, and it has already failed one merge-queue build.
+> 🚧 **BUILT 2026-09-09, PR pending. The owner took option 1: a `--json` payload stops sharing a file descriptor with logging, and the logs move to stderr.** `messagefoundry/__main__.py` `main()` calls `configure_stderr_logging()` before it dispatches, whenever the parsed arguments carry `--json`. That subcommand's log sink is then stderr and stdout carries the payload alone. Three things it deliberately does NOT do. **`logging_guard.py` is untouched** -- its rollover notice still goes to the rolled sink, because the notice landing is what proves the replacement accepted a write, which is the whole stage-1/stage-2 split. **`tests/test_checks.py` keeps asserting `json.loads(capsys.readouterr().out)`** -- that assertion becomes sound rather than optimistic, which is why option 2 was rejected rather than adopted. **`serve`/`supervise` are unchanged** -- they take no `--json`, print no payload, and still log to the stdout NSSM captures, so `docs/SERVICE.md`'s file ownership table and the `service.out.log` runbook steps stay true. `configure_stderr_logging` is reused rather than rebuilt: it already existed for the ADR 0087 sandbox worker, whose stdout carries IPC frames, and it carries the PHI-redaction + control-char-scrub chain that the `logging.lastResort` a handler-less subcommand falls back to today does not.
+>
+> **The regression test is `tests/test_checks.py::test_check_json_payload_survives_a_log_record`.** It installs the guarded stdout sink `serve` installs, points its stream at a CLOSED object (what a capture teardown or a supervisor file-swap leaves behind), forces one record during `check --json`, and asserts stdout parses. Reverted to `main`'s `__main__.py` it fails with exactly the measured `json.decoder.JSONDecodeError: Extra data: line 1 column 5 (char 4)`, on stdout beginning `2026-09-09T...Z WARNING  messagefoundry.logging_guard: application log sink 'stdout' was rolled after a write`. **Forcing the record is what makes it deterministic**; the roll is timing-dependent otherwise, which is why five real failures read as flakes.
+>
+> **Cost, measured 2026-09-09 across every `ci.yml` run since 2026-09-08T20:00Z:** five occurrences on five different branches including a push to `main` itself, and three of 22 merge-queue batches (14 percent), each evicting a healthy pull request into a full re-merge cycle. PRs 885, 981 and 1003 were all evicted this way. **That census is ATTRIBUTED to the seat that dispatched this fix, not re-derived by the seat that built it** -- what was checked here is that the three pull requests exist and are now MERGED, which is consistent with an eviction followed by a re-merge but does not on its own establish the cause. The mechanism does not rest on the census: it is reproduced deterministically by the regression test above.
+>
+> **Filed 2026-09-08 -- not started.** `messagefoundry/logging_guard.py` (shipped by PR #883 at 07:24Z, commit `995fc2790`) writes `application log sink stdout was rolled after a write` to the **stdout sink**. A CLI command invoked with `--json` writes its payload to that same stream, so a reader doing `json.loads(...)` sees the notice first and raises `Extra data: line 1 column 5`. Six tests in `tests/test_checks.py` fail this way, and it has already failed one merge-queue build.
 >
 > **Scored 2026-09-08 -> P2.** Value **6/10** · Difficulty **3/10** · _quick win_. Value 6 -- it makes `--json` output unreliable for any consumer, and it evicts merge-queue entries at random. Difficulty 3 -- the notice needs a stream that is not the machine-readable one.
 

messagefoundry/__main__.py

@@ -37,6 +37,7 @@
     LogFile,
     SyslogForward,
     configure_logging,
+    configure_stderr_logging,
     query_sntp_offset,
 )
 
@@ -876,6 +877,26 @@ def main(argv: list[str] | None = None) -> int:
     )
 
     args = parser.parse_args(argv)
+    # A `--json` subcommand's stdout is a machine-parsed document, so NOTHING else may write there
+    # (BACKLOG #1489). The engine's default log sink is stdout too, and one log line ahead of the
+    # payload makes `json.loads` raise `Extra data: line 1 column 5`, because the text format opens
+    # with the ISO timestamp: `2026` parses as a number and the payload becomes trailing garbage.
+    # It cost real CI time before it was fixed; the census lives on the ledger item, with its
+    # provenance, rather than being restated here.
+    #
+    # DECIDED HERE, and not in `logging_guard`, which is where the symptom shows up. That module
+    # writes its rollover notice to the ROLLED SINK on purpose: the notice landing is the proof that
+    # the replacement stream accepted a write, which is precisely what separates stage 1 (healed)
+    # from stage 2 (unwritable). Move the notice and the fail-closed halt loses its trigger. The
+    # collision is two contracts on one file descriptor, and the CLI is what owns that choice.
+    #
+    # `configure_stderr_logging` is the shipped answer to "this process's stdout is not a log
+    # channel" (the ADR 0087 sandbox worker, whose stdout carries IPC frames), and it carries the
+    # PHI-redaction + control-char-scrub filter chain, which is strictly more than the UNFILTERED
+    # `logging.lastResort` a handler-less subcommand degrades to today. `serve` and `supervise` take
+    # no `--json`, print no payload and are untouched: they still log to the stdout NSSM captures.
+    if getattr(args, "json", False):
+        configure_stderr_logging()
     return _DISPATCH[args.command](args)
 
 

messagefoundry/logging_setup.py

@@ -1095,13 +1095,17 @@ 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**, 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.
+    For a MessageFoundry process whose **stdout is not a log channel**. Two shapes reach here, and the
+    second is why this is not sandbox-specific machinery. (1) A child whose stdout is a **binary
+    channel**: the ADR 0087 sandbox worker, whose stdout carries the MFW2 IPC frames, so a stray log
+    byte written there would corrupt a frame. (2) A **CLI subcommand invoked with ``--json``**, whose
+    stdout carries one machine-parsed document; ``__main__.main`` calls this before dispatch and
+    carries the measurement (BACKLOG #1489). The obvious way to express either,
+    ``logging.basicConfig(stream=sys.stderr)``, gets the 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.

tests/test_checks.py

@@ -4,15 +4,21 @@
 
 from __future__ import annotations
 
+import io
 import json
+import logging
 import shutil
+from collections.abc import Iterator
 from pathlib import Path
+from typing import Any
 
 import pytest
 
 import messagefoundry.checks as checks
 from messagefoundry.__main__ import main
-from messagefoundry.checks import run_checks
+from messagefoundry.checks import CheckReport, run_checks
+from messagefoundry.logging_guard import GuardedStreamHandler, active_guard, set_active_guard
+from messagefoundry.logging_setup import configure_logging
 
 SAMPLES_CONFIG = Path(__file__).resolve().parents[1] / "samples" / "config"
 RESULTS_RELAY = Path(__file__).resolve().parents[1] / "samples" / "results_relay"
@@ -128,6 +134,77 @@ def test_check_dryrun_accepts_single_file(
     assert dr["required"] is True and dr["ok"] is True and dr["skipped"] is False
 
 
+# --- stdout belongs to the payload (BACKLOG #1489) ---------------------------
+# Every `_out_json` call above asserts that stdout is pure JSON. That assertion was OPTIMISTIC while
+# the default log sink wrote to stdout as well: it held only for as long as nothing happened to log.
+# The test below is the one that makes it SOUND, by forcing the thing that used to break it.
+
+#: Distinctive enough that finding it in a stream is evidence about THIS record, not a coincidence.
+_LOG_MARKER = "a log record fired during a --json subcommand"
+
+
+@pytest.fixture
+def _restore_root_logger() -> Iterator[None]:
+    """``configure_logging`` mutates the global root logger AND publishes a process-wide write guard;
+    restore both, or a handler bound to this test's capture stream outlives it (which is the very
+    failure this section is about)."""
+    root = logging.getLogger()
+    saved_handlers = root.handlers[:]
+    saved_level = root.level
+    saved_guard = active_guard()
+    try:
+        yield
+    finally:
+        for handler in root.handlers[:]:
+            root.removeHandler(handler)
+        for handler in saved_handlers:
+            root.addHandler(handler)
+        root.setLevel(saved_level)
+        set_active_guard(saved_guard)
+
+
+@pytest.mark.usefixtures("_restore_root_logger")
+def test_check_json_payload_survives_a_log_record(
+    monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str]
+) -> None:
+    """A record logged DURING ``check --json`` must not reach stdout.
+
+    The shape that evicted merge-queue entries (BACKLOG #1489 carries the census): a process that
+    configured the engine's logging keeps the guarded stdout sink on the root logger, and its stream
+    object later goes stale (pytest's capture teardown, an NSSM capture-file swap, a closed pipe).
+    The next record fails to write, so the guard rolls the sink onto the LIVE ``sys.stdout`` and
+    records the rollover event there, landing ahead of the payload; ``json.loads`` then raises
+    ``Extra data: line 1 column 5`` on the ISO timestamp. Forcing the record is what makes that
+    deterministic. It is timing-dependent otherwise, which is exactly why the real failures read as
+    flakes.
+
+    The guard is doing the right thing and is not touched: writing the notice to the rolled sink is
+    how stage 1 proves the replacement accepted a write. What changes is that a ``--json`` subcommand
+    no longer leaves a log sink pointed at the stream its payload is going to.
+    """
+    configure_logging("INFO")
+    stdout_sink = logging.getLogger().handlers[0]
+    assert isinstance(stdout_sink, GuardedStreamHandler)
+    # A CLOSED stream, which is what a capture teardown or a supervisor file-swap leaves behind: the
+    # write raises, and the guard re-resolves to whatever `sys.stdout` is now.
+    stale = io.StringIO()
+    stale.close()
+    monkeypatch.setattr(stdout_sink, "stream", stale)
+
+    real_run_checks = checks.run_checks
+
+    def _run_checks_and_log(*args: Any, **kwargs: Any) -> CheckReport:
+        logging.getLogger("messagefoundry.test").warning(_LOG_MARKER)
+        return real_run_checks(*args, **kwargs)
+
+    monkeypatch.setattr(checks, "run_checks", _run_checks_and_log)
+
+    assert main(["check", "--config", str(SAMPLES_CONFIG), "--no-lint", "--json"]) == 0
+    captured = capsys.readouterr()
+    assert json.loads(captured.out)["ok"] is True  # stdout carries the payload and nothing else
+    assert _LOG_MARKER in captured.err  # and the record was re-routed, not dropped
+
+
 # --- per-feed fixture mapping (#11) ------------------------------------------
 # A malformed body ERRORs against an HL7 inbound (peek fails) but routes fine against a text inbound
 # (RawMessage, no parse). That asymmetry is a clean discriminator for "did the fixture run only