diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 176a06d41..47ece7759 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. **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. diff --git a/messagefoundry/__main__.py b/messagefoundry/__main__.py index 81060fa90..40df569a1 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. + # 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) 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..533a373dc 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,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