From 7e6b2bf79de731b02f6ba84508c7497ea9a119d3 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 9 Sep 2026 09:39:05 -0500 Subject: [PATCH 1/2] fix(cli): a --json payload no longer shares stdout with the log (BACKLOG #1489) `messagefoundry --json` writes a machine-parsed document to stdout, and the engine's default log sink writes human-readable lines to the same descriptor. One log line ahead of the payload makes `json.loads` raise `Extra data: line 1 column 5`: the text format opens with the ISO timestamp, so `2026` parses as a number and the payload becomes trailing garbage. 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 evicted this way. `main()` now calls `configure_stderr_logging()` before it dispatches, whenever the parsed arguments carry `--json`. That subcommand's log sink is stderr; stdout carries the payload alone. Three things this deliberately does not do. `logging_guard.py` is untouched. Its rollover notice goes to the ROLLED SINK on purpose, and the module says so: 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). Sending the notice to stderr would leave stage 1 unable to tell a healed sink from a dead one, so the fail-closed halt would lose its trigger. The item's first prescription said to do that and was retracted before it merged; this change does not revive it. `tests/test_checks.py` keeps asserting `json.loads(capsys.readouterr().out)`. That assertion was optimistic while a log sink pointed at stdout, and is sound now. Relaxing it was the other option and was rejected. `serve` and `supervise` are unchanged. They take no `--json` and print no payload, so they still log to the stdout NSSM captures, and `docs/SERVICE.md`'s log-ownership table and `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 MFW2 IPC frames. Its docstring now names both callers. It also carries the PHI-redaction and control-char-scrub filter chain, which the `logging.lastResort` fallback a handler-less subcommand degrades to today does not. Regression test: `tests/test_checks.py::test_check_json_payload_survives_a_log_record` 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 and the record reached stderr. 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. Checks run: ruff format and ruff check on the three changed .py files (clean); mypy strict over `messagefoundry` (273 files, no issues); `scripts/docs/backlog_status_check.py` (720 items, one status each, 6 advisory warnings, none from this change); pytest over `tests/test_checks.py`, the 25 other test files that pass `--json` to `main`, `tests/test_logging.py` and `tests/test_backlog_status_check.py` (886 passed, 1 skipped), and separately `tests/test_asvs_phase0.py` and `tests/test_audit_offbox_tee.py` (156 passed, 1 skipped). Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 8 +++- messagefoundry/__main__.py | 21 +++++++++ messagefoundry/logging_setup.py | 18 +++++--- tests/test_checks.py | 78 ++++++++++++++++++++++++++++++++- 4 files changed, 116 insertions(+), 9 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 176a06d41..dc862acf7 100644 --- a/docs/BACKLOG.md +++ b/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. +> +> **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. diff --git a/messagefoundry/__main__.py b/messagefoundry/__main__.py index 81060fa90..3deaa0f2c 100644 --- a/messagefoundry/__main__.py +++ b/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. + # Measured 2026-09-09 over ci.yml: five failures on five branches in a day, three of them + # evicting a healthy merge-queue batch. + # + # 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) diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index 0b54bf0e3..7ffd436d3 100644 --- a/messagefoundry/logging_setup.py +++ b/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. diff --git a/tests/test_checks.py b/tests/test_checks.py index ee386c017..c8f49d6af 100644 --- a/tests/test_checks.py +++ b/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,76 @@ 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 three merge-queue batches: 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 five 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 From 559c5b9cdf6796b3e3f398ab9810d670eaa223f8 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 9 Sep 2026 09:42:40 -0500 Subject: [PATCH 2/2] docs(backlog): say who measured the CI census this fix cites (BACKLOG #1489) The previous commit wrote "measured 2026-09-09 across every ci.yml run since 2026-09-08T20:00Z" into the ledger, a code comment and a test docstring. This seat did not run that census; it came from the seat that dispatched the work. Recording someone else's measurement as your own is how an unverifiable number becomes a fact three readers later. The ledger item now carries the census once, marked ATTRIBUTED, alongside the one thing checked here: PRs 885, 981 and 1003 exist and are MERGED, which is consistent with an eviction followed by a re-merge but does not on its own establish the cause. The code comment and the test docstring stop restating it and point at the item instead, which is also what SDS-3.5 asks for. Nothing about the fix or the regression test changes. The mechanism never rested on the census: it is reproduced deterministically by `tests/test_checks.py::test_check_json_payload_survives_a_log_record`, which fails without the change with the exact measured JSONDecodeError. Checks re-run: ruff format and ruff check on both changed .py files (clean); mypy strict over `messagefoundry` (273 files, no issues); `scripts/docs/backlog_status_check.py` (720 items, one status each, same 6 advisory warnings); `pytest tests/test_checks.py` (39 passed, 1 skipped). Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 2 +- messagefoundry/__main__.py | 4 ++-- tests/test_checks.py | 15 ++++++++------- 3 files changed, 11 insertions(+), 10 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index dc862acf7..47ece7759 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -27828,7 +27828,7 @@ connection-scaling guard. > > **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. +> **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. > diff --git a/messagefoundry/__main__.py b/messagefoundry/__main__.py index 3deaa0f2c..40df569a1 100644 --- a/messagefoundry/__main__.py +++ b/messagefoundry/__main__.py @@ -881,8 +881,8 @@ def main(argv: list[str] | None = None) -> int: # (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. - # Measured 2026-09-09 over ci.yml: five failures on five branches in a day, three of them - # evicting a healthy merge-queue batch. + # 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 diff --git a/tests/test_checks.py b/tests/test_checks.py index c8f49d6af..533a373dc 100644 --- a/tests/test_checks.py +++ b/tests/test_checks.py @@ -169,13 +169,14 @@ def test_check_json_payload_survives_a_log_record( ) -> None: """A record logged DURING ``check --json`` must not reach stdout. - The shape that evicted three merge-queue batches: 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 five real failures read as flakes. + 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