Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/BACKLOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -13218,6 +13218,7 @@ measurement from this row's subject and it is named here rather than performed.*

> 🔢 **Re-scored 2026-08-20 -> P3.** Value **4/10** · Difficulty **2/10** · _fill-in_. One limb remains and it is a pure refactor: logging_setup.py:66-70 still derives its own table from range(0x20) plus 0x7F and does not import controlchars at all, while the module now states the alphabet once at :67 with both arms reading it. Value 4 because nothing is mis-screened today, two of the three named copies already agree, and at least two further independent derivations sit outside this item's scope (spreadsheet.py:37, soap.py:263), so folding logging_setup in buys the stated cross-module leverage for one file rather than repo-wide. Difficulty 2 for one import, one derivation with an explicit tab subtraction, a test pinning that tab stays excluded, and renaming the acceptance test's scrub_control_chars, which returns zero code hits. _(previously unscored.)_
>
> **PARTIAL 2026-08-25 -- THE THIRD SPELLING IS NOW GONE TOO. STILL STAYS OPEN** (spreadsheet.py:37 and soap.py:263 are named out-of-scope above, and remain so). `logging_setup.py` now imports `controlchars` and states its own table as that alphabet minus TAB, proved byte-identical to the pre-change table entry-for-entry (32 entries both sides) rather than asserted. Verified before writing this note, not taken from the branch's own claim.
> **PARTIAL 2026-08-20 -- ONE OF THE TWO SPELLINGS INSIDE THE MODULE IS GONE; THE THIRD, IN ANOTHER MODULE, IS NOT. THIS ITEM STAYS OPEN.** `controlchars.py` now states the set once, in `_is_control_char` at `:67`, and both `has_control_char` and `strip_control_chars` read it -- so the module's own interior no longer contradicts its docstring. **But `logging_setup.py:66-70` still re-derives the same set independently** (`for _i in range(0x20)` plus `[0x7F]`), and the landing branch does not touch that file at all. The item names **three** spellings and asks for **one definition of the SET**; two of three now share one. **The leverage the module exists to provide is still absent across the module boundary:** widen `_is_control_char` and it reaches neither `_CTRL_TRANSLATION` nor anything reading it, and nothing reports the omission. Measured on the landing branch, not inferred. Recorded by the lander under ADR 0165, because a closing banner that lists what a change fixed and not what it left is half a record.
> 🔢 **Filed 2026-08-15 - not started. THE CONSOLIDATION DOES NOT CONSOLIDATE ITS OWN TWO FUNCTIONS.** [`controlchars.py`](../messagefoundry/controlchars.py) was created by [#1253](BACKLOG.md) to write the C0/DEL test **once**; its docstring is titled *"The C0/DEL control-character test, written once"* and ends *"THE POINT IS THE COPYING PRACTICE, not the seven known lines. If you need this test, import it."* **It then spells the predicate out twice inside itself**, and a third statement of the same set lives in `logging_setup`.
> **MEASURED, three independent spellings of one set:**
Expand Down
32 changes: 29 additions & 3 deletions messagefoundry/logging_setup.py
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,10 @@
from typing import Any

from messagefoundry.config.tls_policy import harden_cipher_suites

# A LEAF MODULE, imported for its DEFINITION rather than its behaviour (BACKLOG #1273). controlchars
# imports nothing from this package, so there is no cycle -- checked by import, not assumed.
from messagefoundry.controlchars import _is_control_char
from messagefoundry.redaction import redact

__all__ = [
Expand Down Expand Up @@ -64,11 +68,33 @@

# C0 control characters (and DEL) escaped to keep one log record on one line. CR/LF are the
# log-injection vector; tab (0x09) is left intact as benign whitespace.
#
# THE ALPHABET IS controlchars._is_control_char's, MINUS TAB (BACKLOG #1273, limb 3). It used to be
# re-derived here as `range(0x20)` plus a separate `0x7F` line -- a second statement of the same set
# in a codebase whose controlchars module exists precisely to state it once. The two agreed, so
# nothing was mis-escaped; the cost is the future-tense one #1239 named and #1253 acted on, that a
# later widening applied to one copy silently does not apply to the other.
#
# THE SUBTRACTION IS THE POINT, so it is written as one. Documenting this as "excluded" and leaving
# the copy was considered and is refuted by the residual block on #1273: the parsing/sniff.py
# carve-out earns its separate definition by being BYTE-wise and subtracting a whole allowlist,
# while this is CHARACTER-wise, escapes CR/LF rather than tolerating them, and differs by EXACTLY
# ONE code point. Measured: controlchars 33 code points, this table 32, symmetric difference {0x09}.
# One code point of divergence is a subtraction, not a different predicate.
_CTRL_TRANSLATION: dict[int, str] = {0x0A: "\\n", 0x0D: "\\r"}
for _i in range(0x20):
if _i not in (0x09, 0x0A, 0x0D):
# RANGE 0x100, NOT 0x80, AND THAT IS THE DIFFERENCE BETWEEN A REAL FOLD AND A COSMETIC ONE. The
# alphabet is C0+DEL today, so both bounds produce the identical 32 entries -- proved by the
# byte-identity check in the commit. But `_is_control_char`'s docstring names widening to C1
# (U+0080-U+009F) as the deliberate change this shared module exists to make cheap, and a 0x80 bound
# would silently NOT follow it: the escape table would keep the old alphabet while every other call
# site moved, which is the exact two-copy drift limb 3 removes. Iterating past the current boundary
# costs 128 predicate calls at import and makes the widening propagate by construction.
for _i in range(0x100):
# TAB IS THE ONLY SUBTRACTION and test_tab_is_the_only_control_character_left_intact pins it.
# CR/LF are excluded from this loop because they get readable escapes above, not because they
# are tolerated -- they are the injection vector this whole table exists for.
if _is_control_char(chr(_i)) and _i not in (0x09, 0x0A, 0x0D):
_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
Expand Down
63 changes: 63 additions & 0 deletions tests/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -927,3 +927,66 @@ def test_serve_time_sync_ok_within_threshold_starts_clean(
["serve", "--config", str(tmp_path), "--db", str(tmp_path / "x.db"), "--env", "dev"]
)
assert rc == 0


# --- BACKLOG #1273 limb 3: ONE definition of the alphabet, with the tab subtraction pinned -------
#
# `_CTRL_TRANSLATION` used to re-derive the control-character set as `range(0x20)` plus a separate
# `0x7F` line -- a second statement of the set that `controlchars` exists to state once. The two
# agreed, so nothing was mis-escaped. The cost was the future-tense one: a later widening applied to
# one copy silently does not apply to the other, and nothing reports the omission.
#
# These tests pin the RELATIONSHIP rather than either set's contents, which is what survives a
# deliberate widening: widen `_is_control_char` and the table follows automatically, and if it does
# not, the first test goes red naming the code points that drifted.


def test_the_log_escape_table_is_the_controlchars_alphabet_minus_tab() -> None:
"""The whole of limb 3, as one assertion about the DIFFERENCE.

Not "the table has 32 entries" -- that pins a number and would have to be edited by whoever
widens the alphabet, which is precisely the person who should be told rather than asked to
update a constant. This pins the SUBTRACTION, so a legitimate widening passes untouched and a
divergence names its own code points.
"""
from messagefoundry.controlchars import _is_control_char
from messagefoundry.logging_setup import _CTRL_TRANSLATION

alphabet = {cp for cp in range(0x80) if _is_control_char(chr(cp))}
escaped = set(_CTRL_TRANSLATION)

assert alphabet - escaped == {0x09}, (
f"the log escape table and controlchars have drifted: "
f"{sorted(hex(c) for c in (alphabet - escaped) - {0x09})} are screened as control "
f"characters but not escaped in a log line"
)
assert not escaped - alphabet, (
f"the log table escapes {sorted(hex(c) for c in escaped - alphabet)}, which controlchars "
f"does not treat as control characters -- one of the two has been widened alone"
)


def test_tab_is_the_only_control_character_left_intact() -> None:
"""Tab is benign whitespace in a log line; CR/LF are the injection vector and must not join it.

The asymmetry is the reason this is a separate test from the one above: that one would still
pass if tab were swapped for CR in the subtraction, because the difference would still be a
single code point.
"""
from messagefoundry.logging_setup import _CTRL_TRANSLATION

assert 0x09 not in _CTRL_TRANSLATION, "tab must survive a log line unescaped"
assert _CTRL_TRANSLATION[0x0A] == "\\n", "LF is the injection vector and must be escaped"
assert _CTRL_TRANSLATION[0x0D] == "\\r", "CR is the injection vector and must be escaped"
assert _CTRL_TRANSLATION[0x00] == "\\x00"
assert _CTRL_TRANSLATION[0x7F] == "\\x7f", "DEL is in the alphabet and must still be escaped"


def test_a_tab_survives_the_real_scrub_and_a_newline_does_not() -> None:
"""Drives the shipped filter rather than the table, so the two cannot agree while the code differs."""
from messagefoundry.logging_setup import _CTRL_TRANSLATION

scrubbed = "before\tafter\nnext".translate(_CTRL_TRANSLATION)
assert "\t" in scrubbed, "the tab was escaped; a log line lost its benign whitespace"
assert "\n" not in scrubbed, "a real newline survived; one record can now forge a second line"
assert scrubbed == "before\tafter\\nnext"
Loading