diff --git a/CHANGELOG.md b/CHANGELOG.md index 5b794a21..9ddf65bc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -64,6 +64,17 @@ All notable changes to MessageFoundry are documented here. The format follows documenting the weakness without changing the gate. ### Fixed +- **A CR/LF inside an exception message could forge a whole log line on the text sink.** + `ControlCharScrubFilter` escaped only the rendered message, and `logging.Formatter` appends a record's + traceback (`exc_text`) and stack dump (`stack_info`) **verbatim** — so a newline-bearing exception + string landed at column 0 on its own physical line, where a payload padded to the record layout was + byte-indistinguishable from a real entry to an operator or a line-oriented SIEM parser. Both fields + are now scrubbed too (ASVS 16.4.1; the residual ADR 0034 §1 disclosed, BACKLOG #335). **Visible + change:** a traceback is *not* collapsed onto one line — its line breaks are kept and every line is + indented with ` | `, so it stays readable while no line of it can start at column 0. A log parser + keyed on `Traceback (most recent call last):` at the start of a line needs that prefix added. The + JSON sink is unchanged in substance (`json.dumps` already escaped these fields); its `exception` + and `stack` values now carry the same indent. - **The DICOM C-STORE SCP's fail-closed refusal named a settings key that does not exist.** It told the operator to set `[inbound].source_ip_allowlist`; `InboundSettings` has no such field and section models ignore unknown keys, so an operator following the engine's **own error message** wrote a key diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 3ea9ac61..a6f673e0 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -231,7 +231,7 @@ Ordered by value descending, then difficulty ascending (cheapest first at equal | 52 | **#124** | Batch-export message bodies from a connection log to a file | 4 | 3 | _fill-in_ | DEMAND-GATE | Console polish now that the capability itself ships — a scripted operator exports today through the audited step-up route, leaving only the save-selected affordance; the JS is already written (`messagefoundry_webconsole/static/app.js:1380`), so the cost is emitting the `data-mf-*` attributes and row checkboxes in `pages/messages.py` and registering `/ui/messages/export` ahead of `/ui/messages/{message_id}` (`routes/core.py:468`) so the path parameter cannot swallow it. | | 53 | **#133** | User-chosen display colour on configuration objects | 4 | 3 | _fill-in_ | DEMAND-GATE | Value 4 ("DX or console polish") is right and the stale-citation finding is right (no messagefoundry/console/ package; the live chrome is _html.py's page() head). But D3→2 rests on "a colour is that same shape [as `flagged`] plus a render", and that is false in a way this codebase enforces. `flagged` is a bool with no rendering sink; a colour is an operator-supplied STRING rendered into console markup, and the /ui CSP is `style-src 'self'` with no 'unsafe-inline' (_security.py:205, _auth.py:141, and app.css:2 states the constraint outright). An inline `style="…"` colour would simply not render, so the build must either bind a fixed palette to CSS classes shipped in app.css or add a nonce'd style mechanism the CSP does not currently grant for styles — a design decision plus value validation on untrusted config input, on top of the config-model → TOML → API → console thread. That is D3 ("a new setting into one connector"-scale work), not D2's "default flip or doc edit"-adjacent band. Quadrant stays fill-in; tier stays DEMAND-GATE. | | 54 | **#234** | Steps view projection refreshes on save only | 4 | 3 | _fill-in_ | P3 | UX latency on an opt-in authoring surface, not a correctness gap — the rows merely lag the buffer while live values stay correctly save-gated (ide/src/stepsView.ts:327); the debounce already exists at :89, but relaxing a deliberate ADR 0076 §5 guardrail means an amendment plus proving `EditLoopGuard` holds when projection races an in-flight `lens rewrite`. | -| 55 | **#335** | Control-char scrub misses `exc_text`/`stack_info` | 4 | 3 | _fill-in_ | P3 | `ControlCharScrubFilter.filter` still translates only `record.getMessage()` while `RedactionFilter` is the sole toucher of `exc_text`/`stack_info` (`logging_setup.py:124-131`), so a CR/LF traceback can forge a record on the text sink — but `JsonFormatter` escapes C0 regardless, the off-box forwarder defaults to json, and the message-path `exc_info` sites are a handful of non-peer-derived guards, so it is log-record integrity on one sink; the filter already runs last, so the cost is the readability call ADR 0034:146 defers plus tests and an ADR amendment. | +| 55 | **#335** | Control-char scrub misses `exc_text`/`stack_info` | 4 | 3 | _fill-in_ | P3 | ✅ **DONE 2026-08-04** — see the item's banner. The row is retained because the rank column and the open-item census above this table are recomputed as one pass, which this commit deliberately does not run; treat the census as one item stale until it does. As filed: `ControlCharScrubFilter.filter` translated only `record.getMessage()` while `RedactionFilter` was the sole toucher of `exc_text`/`stack_info`, so a CR/LF traceback could forge a record on the text sink. | | 56 | **#343** | Sandbox child stderr is inherited unframed into the engine log stream | 4 | 3 | _fill-in_ | P3 | The worker is still spawned `stderr=None` (`pipeline/sandbox.py:266`), so a sandboxed Handler's bytes land in the engine's own log stream unattributed and a `print()` of a body writes PHI at whatever level the operator runs — but the same `print()` under the default `mode=off` reaches the same stream, so the sandbox-specific loss is attribution and the fd-1 framing that survives on luck rather than design; a `stderr=subprocess.PIPE` relay thread through the stdlib logger (inheriting the existing PHI filters) plus a bootstrap redirect of the child's `sys.stdout`, all inside one module. | | 57 | **#346** | The sandbox import boundary is enforced only at runtime, under an off-by-default flag | 4 | 3 | _fill-in_ | P3 | The scorer verified the item's own measurement (`FORBIDDEN_MODULES` appears nowhere under `tests/`, confirmed) and inherited its conclusion — but the conclusion is the part that is false. The item's load-bearing claim is that "a re-violation is invisible to a green suite" because the guard runs only in the child under a non-default flag. `tests/test_sandbox.py` runs REAL `mode=SUBPROCESS` sessions across roughly a dozen tests (`test_subprocess_parity_router_and_handler`, `test_subprocess_marshals_live_store_run_context`, `test_generator_router_routes_under_mode_subprocess`, `test_setstate_tuple_and_nonfinite_values_survive_mode_subprocess`, ...) — the child is genuinely spawned, since the OFF test asserts `off._proc is None` as the distinguishing property. Decisively, `test_response_view_reaches_a_sandboxed_handler` (~:617-645) drives a `CapturedResponse` through a live subprocess round-trip, i.e. the exact violation instance the item is built on would now be caught red by CI. So the compensating control is a live test file, not absent, and the residual narrows to a FUTURE codec type added without an accompanying subprocess-mode test. That is test-coverage hardening = value 4, not "real gap, awkward workaround" = 6. Difficulty 3 stands (an `ast` walker anchored on the constant, falsified against a planted import). At value 4 the tier is P3 (P2 needs value >= 5) and the quadrant is fill-in. | | 58 | **#351** | SQL Server failover test asserts on a 0.35s wall-clock margin across a real DB round-trip | 4 | 3 | _fill-in_ | P3 | One observation on one leg, with the 2022 leg passing the same commit and a sibling PR passing both, bounds this to a marginal test whose red misattributes to whichever PR it fires on — the residual worth is settling whether #348's work at the `_acquire` chokepoint merely spent latency the test had no headroom for or tipped a real delay-predicate regression; the edit is confined to one test file, but it cannot be validated locally by default (the SQL Server leg silently skips) and must not be landed as a wider margin before the question is answered. | @@ -3291,7 +3291,7 @@ What is *not* covered is the thing that will grow: `.semgrep/messagefoundry.yml` ## 335. Control-char scrub misses `exc_text`/`stack_info` -> 🔢 **Filed 2026-08-01 — not started.** Value **4/10** · Difficulty **3/10** · _fill-in_. `ControlCharScrubFilter.filter` still translates only `record.getMessage()` while `RedactionFilter` is the sole toucher of `exc_text`/`stack_info` (`logging_setup.py:124-131`), so a CR/LF traceback can forge a record on the text sink — but `JsonFormatter` escapes C0 regardless, the off-box forwarder defaults to json, and the message-path `exc_info` sites are a handful of non-peer-derived guards, so it is log-record integrity on one sink; the filter already runs last, so the cost is the readability call ADR 0034:146 defers plus tests and an ADR amendment. +> ✅ **DONE (2026-08-04).** `ControlCharScrubFilter.filter` now applies `_CTRL_TRANSLATION` to `record.exc_text` and `record.stack_info` as well as the rendered message, so a CR/LF-bearing traceback can no longer forge a record on the text sink. The readability call ADR 0034 §1 deferred was taken explicitly and amended there in the same commit: the traceback is **not** collapsed to one line — its line breaks are kept and every line is indented with `_CONTINUATION_PREFIX` (`" | "`), so no traceback line starts at column 0 and none can impersonate `_LOG_FORMAT`. Pinned by the `test_control_char_*` tests in `tests/test_logging.py`. One residual stays open and is recorded in ADR 0034 §1: a handler carrying this filter *without* `RedactionFilter` would still hand the formatter an unrendered `exc_info` — no shipped handler is in that state. Scored **4/10** value · **3/10** difficulty when filed 2026-08-01. **Cluster:** Security / Logging. **Priority:** P3. **Verdict:** build (small). **Severity:** low. diff --git a/docs/adr/0034-static-analysis-triage-policy-accepted-risk-register.md b/docs/adr/0034-static-analysis-triage-policy-accepted-risk-register.md index 4dfc96d5..f4b1c6d4 100644 --- a/docs/adr/0034-static-analysis-triage-policy-accepted-risk-register.md +++ b/docs/adr/0034-static-analysis-triage-policy-accepted-risk-register.md @@ -141,10 +141,18 @@ the class rationale **must not be inherited** by a future finding on a `log.exce `exc_info=True` site — the engine has many (the delivery/router/transform catches, the `_on_*_worker_done` callbacks, the pollers). `JsonFormatter` escapes `exc_text` through `json.dumps`, so the off-box forwarder (JSON by default) is unaffected; the residual is the human-readable stdout/NSSM text log. -**Open hardening (not done):** apply `_CTRL_TRANSLATION` to `exc_text`/`stack_info` in -`ControlCharScrubFilter` — it runs after `RedactionFilter`, so `exc_text` is already populated. It is a -few lines, but it collapses every traceback to one physical line, which is an operator-facing -readability change and wants an explicit decision rather than a drive-by edit. +**Open hardening — CLOSED 2026-08-04 (BACKLOG #335).** `ControlCharScrubFilter` now scrubs +`record.exc_text` and `record.stack_info` as well as the rendered message. The readability decision +deferred above was taken explicitly, and it is **not** the collapse-to-one-line this paragraph feared: +the traceback keeps its line breaks and every line is indented with `_CONTINUATION_PREFIX`, so no +traceback line begins at column 0 and none can impersonate the `_LOG_FORMAT` record prefix. Why the +block's *first* line is indented too, and why re-application is idempotent (every handler carries its +own filter chain, so one record is scrubbed once per sink), is recorded at `_scrub_block`; the property +is pinned by the `test_control_char_*` tests in `tests/test_logging.py`. **One residual survives, so the +register line at `:40` still reads wider than the code:** a handler carrying `ControlCharScrubFilter` +*without* `RedactionFilter` hands the formatter an unrendered `exc_info` that no filter has touched. No +shipped handler is in that state — `_install_phi_filters` installs both — but that is a construction +guarantee, not a scrub. The paragraph above stands as the record of what was true before. **2. `PinnedDependenciesID` — the blanket rationale was applied too widely.** "CI installs editably (`pip install -e .[extras]`), which cannot use `--require-hashes`" is true of the editable installs and diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index 5fb3c095..2a3d78ef 100644 --- a/messagefoundry/logging_setup.py +++ b/messagefoundry/logging_setup.py @@ -68,6 +68,30 @@ _CTRL_TRANSLATION[_i] = f"\\x{_i:02x}" _CTRL_TRANSLATION[0x7F] = "\\x7f" +#: Stamped on every physical line of a record's ``exc_text``/``stack_info`` (BACKLOG #335). A traceback +#: is multi-line by nature, so collapsing it the way the rendered message is collapsed would cost the +#: operator the readability an incident depends on. Its line breaks are kept and every line is indented +#: instead, so no traceback line starts at column 0 and none can impersonate the ``_LOG_FORMAT`` record +#: prefix (ASVS 16.4.1 — the readability call ADR 0034 §1 deferred). +_CONTINUATION_PREFIX = " | " + + +def _scrub_block(text: str) -> str: + """Escape control characters in a multi-line block (``exc_text``/``stack_info``) while KEEPING its + line breaks, indenting every line with :data:`_CONTINUATION_PREFIX`. + + The **first** line is indented too, so the guarantee does not rest on it being the stdlib + ``Traceback (most recent call last):`` header: ``Formatter.formatException`` emits no header at all + when the exception carries no ``__traceback__``, and that first line is then peer-derived text. + + Idempotent — the prefix is stripped before it is re-applied — because every handler carries its own + filter chain, so a record dispatched to stdout *and* the off-box forwarder is scrubbed twice and the + two sinks must not disagree.""" + return "\n".join( + _CONTINUATION_PREFIX + line.removeprefix(_CONTINUATION_PREFIX).translate(_CTRL_TRANSLATION) + for line in text.split("\n") + ) + class ControlCharScrubFilter(logging.Filter): """Neutralize CR/LF and other control characters in the rendered log message to prevent log @@ -76,7 +100,13 @@ class ControlCharScrubFilter(logging.Filter): Untrusted MLLP peer data and HL7-derived exception text reach the general log; without this a crafted value containing a newline could inject a forged log line into NSSM's captured stdout. We render the message (applying ``%`` args) once, escape any control characters, and only then - replace ``record.msg`` — clean messages keep their lazy ``msg``/``args`` untouched.""" + replace ``record.msg`` — clean messages keep their lazy ``msg``/``args`` untouched. + + ``record.exc_text`` and ``record.stack_info`` are covered too (BACKLOG #335, ADR 0034 §1), via + :func:`_scrub_block`. This filter is installed **last** (see :func:`_install_phi_filters`), so + :class:`RedactionFilter` has already rendered ``exc_info`` into ``exc_text`` and cleared it; a + handler carrying this filter *without* that one would leave an unrendered ``exc_info`` for the + formatter to expand unscrubbed.""" def filter(self, record: logging.LogRecord) -> bool: message = record.getMessage() @@ -84,6 +114,14 @@ def filter(self, record: logging.LogRecord) -> bool: if scrubbed != message: record.msg = scrubbed record.args = () + # The rendered message is only half the record: ``Formatter.format`` appends ``exc_text`` and + # ``stack_info`` VERBATIM, so a CR/LF inside an exception message forged a whole line on the + # text sink (BACKLOG #335). ``RedactionFilter`` is installed first and renders ``exc_info`` + # into ``exc_text``, so both fields are already populated when this filter runs. + if record.exc_text: + record.exc_text = _scrub_block(record.exc_text) + if record.stack_info: + record.stack_info = _scrub_block(record.stack_info) return True diff --git a/tests/test_logging.py b/tests/test_logging.py index 02da8193..3065cd1f 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -19,9 +19,11 @@ from messagefoundry import __main__ from messagefoundry.logging_setup import ( ControlCharScrubFilter, + CredentialQueryScrubFilter, JsonFormatter, RedactionFilter, SyslogForward, + _make_formatter, configure_logging, ) @@ -248,6 +250,59 @@ def test_redaction_filter_residual_bare_name_not_caught() -> None: assert "DOE^JANE" in out # accepted residual: a single-delimiter bare name passes through +# --- BACKLOG #335: the control-char scrub covers exc_text / stack_info ------- + +#: A payload shaped exactly like a real record under ``_LOG_FORMAT`` (level padded to eight columns). +_FORGED_RECORD = "2026-08-01T00:00:00Z INFO messagefoundry.auth: FORGED admin login ok" +#: Matches a line that OPENS with the production record prefix (a UTC stamp at column 0). +_RECORD_PREFIX_RE = re.compile(r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}Z ") + + +def _production_lines(record: logging.LogRecord) -> list[str]: + """Render ``record`` the way a text sink does: the production filter chain, in the order + ``_install_phi_filters`` installs it, then the production text formatter.""" + for scrub in (RedactionFilter(), CredentialQueryScrubFilter(), ControlCharScrubFilter()): + scrub.filter(record) + return _make_formatter("text").format(record).split("\n") + + +def test_control_char_filter_scrubs_exception_traceback() -> None: + # ADR 0034 §1: ``Formatter.format`` appends exc_text VERBATIM, so a CR/LF inside an exception + # message used to land a forged record at column 0 on the text sink (stdout/NSSM, and a + # forward_format="text" collector). Exactly ONE line may open with the record prefix. + try: + raise ValueError(f"boom\n{_FORGED_RECORD}") + except ValueError: + rec = logging.LogRecord( + "mefor.demo", logging.ERROR, __file__, 1, "delivery failed", (), sys.exc_info() + ) + lines = _production_lines(rec) + assert _RECORD_PREFIX_RE.match(lines[0]) # the real record — proves the matcher can SEE one + assert [ln for ln in lines[1:] if _RECORD_PREFIX_RE.match(ln)] == [] + assert "FORGED admin login ok" in "\n".join(lines) # neutralized, not dropped + assert len(lines) > 3, "the traceback must stay multi-line — readability is the deferred call" + + +def test_control_char_filter_scrubs_stack_info() -> None: + # The same vector via stack_info, which the formatter also appends verbatim. + rec = logging.LogRecord("t", logging.ERROR, __file__, 1, "stack dump", (), None) + rec.stack_info = f"Stack (most recent call last):\n{_FORGED_RECORD}" + lines = _production_lines(rec) + assert [ln for ln in lines[1:] if _RECORD_PREFIX_RE.match(ln)] == [] + + +def test_control_char_block_scrub_is_idempotent() -> None: + # Every handler carries its OWN chain, so a record dispatched to stdout AND the off-box forwarder + # is scrubbed twice; a second pass must not re-indent an already-indented block, or the two sinks + # would print different text for the same record. + rec = logging.LogRecord("t", logging.ERROR, __file__, 1, "x", (), None) + rec.exc_text = f"Traceback (most recent call last):\n{_FORGED_RECORD}" + ControlCharScrubFilter().filter(rec) + once = rec.exc_text + ControlCharScrubFilter().filter(rec) + assert rec.exc_text == once + + # --- C2: prod-DEBUG serve guard ----------------------------------------------