From 327804ccfb849bf0dc03433930d8d91e260f1d0d Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 20:55:30 +0000 Subject: [PATCH 1/3] fix(logging): never lose a JSON log record to a serialization error `_format_json` claimed that `default=str` kept a non-serializable `extra` value from costing us the record. It does not. `default` is consulted only for values `json` cannot natively encode, and it is called unguarded, so two inputs still lost the record entirely: - a circular container is rejected structurally, *before* `default` is ever consulted (`ValueError: Circular reference detected`); - a value whose `__str__` raises propagates straight out of `default`. Either one is swallowed by `Handler.handleError`, which drops the record -- the exact outcome the comment said was prevented. Measured through a real handler with three calls, the middle one poisoned: 2 of 3 records reached the sink, both before and after the poisoned one, with the poisoned record gone and 29 lines of stderr noise in its place. Both arrive through the optional-enrichment loop reading `correlation_id` / `performance_ms`. The pre-#1439 JSON template referenced neither, so this is not a regression -- reading those fields is what made the input reachable. No live call site can trigger it: `correlation_id` comes from `record.request_id` and from header values, all strings, and strings are escaped correctly. It needs a future call site passing a container or an object with a raising `__str__`. Fall back to the scalar fields, which cannot fail to serialize, and add a `serialization_error` field naming the cause so the degradation is reported rather than hidden. `except Exception`, deliberately, not a narrow tuple: `(TypeError, ValueError, RecursionError)` looks more correct but the exploding-`__str__` case walks straight through it. The fallback `json.dumps` takes no `default=`, since `safe` holds only natively-encodable scalars -- so it cannot raise and the guarantee is unconditional. Building the detail string is itself guarded, because the failing object's exception could carry a raising `__str__` too. The docstring now states the guarantee the code actually enforces, which is the standard #1429 set and the one this change exists to restore. Closes #1452 --- .../backend/config/logging_config.py | 31 ++++++- tests/unit/test_logging_config_crlf.py | 89 +++++++++++++++++++ 2 files changed, 116 insertions(+), 4 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..d344f5315 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -132,6 +132,10 @@ def _format_json(self, record: logging.LogRecord) -> str: the C0 controls as ``\\n``/``\\r``/``\\uXXXX``, and NEL, LS and PS as non-ASCII ``\\uXXXX``. The record therefore stays a single physical line, which is the same guarantee the line-oriented path provides. + + A record is never lost to a serialization error: if the payload cannot + be serialized at all, the scalar fields are emitted with a + ``serialization_error`` field naming the cause (see #1452). """ payload: dict[str, Any] = { "timestamp": self.formatTime(record, self.datefmt), @@ -156,10 +160,29 @@ def _format_json(self, record: logging.LogRecord) -> str: if hasattr(record, attribute): payload[attribute] = getattr(record, attribute) - # `default=str` keeps a non-serializable `extra` value from raising - # inside the logging path, where an exception would be swallowed and - # the record lost entirely. - return json.dumps(payload, ensure_ascii=True, default=str) + # `default=str` handles values `json` cannot natively encode, but it is + # not sufficient on its own: a circular container is rejected + # structurally *before* `default` is consulted, and a value whose + # `__str__` raises propagates out of `default` itself. Either one would + # be swallowed by `Handler.handleError` and cost us the whole record, so + # fall back to the scalar fields — which cannot fail to serialize — and + # report the loss instead of hiding it. + try: + return json.dumps(payload, ensure_ascii=True, default=str) + except Exception as exc: # noqa: BLE001 - never lose a record + safe = { + key: value + for key, value in payload.items() + if isinstance(value, (str, int, float, bool, type(None))) + } + try: + detail = f"{type(exc).__name__}: {exc}" + except Exception: # noqa: BLE001 - the exception's own __str__ raised + detail = type(exc).__name__ + safe["serialization_error"] = detail + # No `default=`: `safe` holds only natively-encodable scalars, so + # this call cannot raise and the guarantee above is unconditional. + return json.dumps(safe, ensure_ascii=True) def formatException(self, ei) -> str: """Format exception with enhanced stack trace""" diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 509038ae6..fb3cd00f0 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -340,3 +340,92 @@ def test_setup_logging_wires_json_output_to_the_formatter( ] assert formatters, "expected StructuredFormatter on the root logger" assert all(f.json_output is enable_json for f in formatters) + + +# --------------------------------------------------------------------------- +# #1452: `default=str` does not deliver the guarantee its comment states. +# +# `default` is consulted only for values `json` cannot natively encode, and it +# is called unguarded. Two inputs therefore still lose the record entirely -- +# the exact outcome the comment said was prevented. Both arrive through the +# optional-enrichment loop, which is what made them reachable at all. +# --------------------------------------------------------------------------- + + +class _ExplodingStr: + """An `extra` value whose `__str__` raises. + + `default=str` *is* consulted here, and the exception propagates straight + out of it -- so a narrow `except (TypeError, ValueError, RecursionError)` + would not catch this. That is why the guard is `except Exception`. + """ + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _circular_container() -> dict: + """`json.dumps` rejects this structurally, *before* reaching `default`.""" + circular: dict = {} + circular["self"] = circular + return circular + + +@pytest.mark.parametrize( + ("label", "poison"), + [ + ("circular", _circular_container()), + ("exploding-str", _ExplodingStr()), + ], +) +def test_unserializable_enrichment_does_not_lose_the_record(label, poison): + logger, buf = _make_json_logger(f"json-serialization-{label}") + logger.info("payload survives", extra={"request_id": poison}) + + # The record must reach the sink at all -- pre-fix, `logging` swallowed the + # raise via Handler.handleError and dropped it. + rendered = buf.getvalue() + assert rendered.strip(), "record was lost to a serialization error" + + parsed = json.loads(rendered) + # The fields a downstream consumer routes or alerts on stay authoritative. + assert parsed["level"] == "INFO" + assert parsed["logger"] == f"json-serialization-{label}" + assert parsed["message"] == "payload survives" + # And the loss is reported rather than hidden. + assert "serialization_error" in parsed + + +def test_serialization_failure_is_contained_to_its_own_record(): + # The measured pre-fix symptom was "2 of 3 records reaching the sink". + # Neighbouring records must be unaffected in both directions. + logger, buf = _make_json_logger("json-serialization-neighbours") + logger.info("before") + logger.info("poisoned", extra={"request_id": _ExplodingStr()}) + logger.info("after") + + messages = [json.loads(line)["message"] for line in buf.getvalue().splitlines()] + assert messages == ["before", "poisoned", "after"] + + +def test_serialization_fallback_still_emits_one_physical_line(): + # The fallback path must keep the separator guarantee the main path has, + # or a poisoned record could split a log line downstream. + logger, buf = _make_json_logger("json-serialization-oneline") + logger.info("a\nb\r\nc", extra={"request_id": _ExplodingStr()}) + + rendered = buf.getvalue() + assert len(rendered.splitlines()) == 1 + assert rendered.isascii() + assert json.loads(rendered)["message"] == "a\nb\r\nc" + + +def test_benign_json_record_has_no_serialization_error_field(): + # The guard must be inert on the normal path -- no field, no behaviour + # change, for every record that serializes cleanly. + logger, buf = _make_json_logger("json-serialization-benign") + logger.info("nothing wrong here", extra={"request_id": "req-42"}) + + parsed = json.loads(buf.getvalue()) + assert "serialization_error" not in parsed + assert parsed["correlation_id"] == "req-42" From ae76c85dde783e76245ba8768b7c0e8c3ab371aa Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:04:45 +0000 Subject: [PATCH 2/3] fix(logging): drop caller-supplied enrichments from the fallback record CodeRabbit found a real hole in the guard added by the previous commit, and it was in the exact claim that commit asserted could not fail: "`safe` holds only natively-encodable scalars, so this call cannot raise." It can. `int` is a scalar, but CPython caps int/str conversion at 4300 digits, so a large `correlation_id` fails the *primary* `json.dumps` and then fails the fallback identically, because the scalar-type filter retained it. The record was lost anyway -- reproduced through a real handler: previous commit -> record emitted: False | handleError fired: True Filtering by type was the wrong idea. What matters is provenance, not type: the optional enrichments (`performance_ms`, `correlation_id`) are the only caller-supplied values in the payload, so they are the only ones that can carry whatever caused the failure. The fallback now rebuilds from `_JSON_CORE_FIELDS` -- the fields the formatter derives from the LogRecord itself -- and drops the enrichments outright. A third tier backstops it with a constant record. That is what makes the docstring's "never lost" unconditional rather than "covers the failure modes we thought of" -- which is the same overclaim #1452 exists to correct, and the reason for not stopping at tier 2. Tests: +3, all failing against the previous commit's implementation. Focused suite 28 passed; full unit suite delta vs `origin/main` is +8 passed with failures (311) and collection errors (66) unchanged. Closes #1452 --- .../backend/config/logging_config.py | 59 +++++++++++++++---- tests/unit/test_logging_config_crlf.py | 40 +++++++++++++ 2 files changed, 86 insertions(+), 13 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index d344f5315..969360be8 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -62,6 +62,31 @@ } +# The fields ``StructuredFormatter._format_json`` builds itself, as opposed to +# the optional enrichments a call site supplies via ``extra``. Only these are +# retained when the full payload cannot be serialized: they are derived from +# the LogRecord rather than from caller input, so they cannot carry the value +# that caused the failure. See #1452. +_JSON_CORE_FIELDS = ( + "timestamp", + "service", + "version", + "level", + "logger", + "message", + "module", + "line", + "function", + "process", +) + +# Last-resort record. A constant, so emitting it cannot itself fail — which is +# what makes "a record is never lost to a serialization error" unconditional. +_JSON_UNSERIALIZABLE_RECORD = ( + '{"serialization_error": "log record could not be serialized"}' +) + + def sanitize_log_record(rendered: str) -> str: """Neutralize line/record separators in a fully-rendered log record. @@ -133,9 +158,11 @@ def _format_json(self, record: logging.LogRecord) -> str: non-ASCII ``\\uXXXX``. The record therefore stays a single physical line, which is the same guarantee the line-oriented path provides. - A record is never lost to a serialization error: if the payload cannot - be serialized at all, the scalar fields are emitted with a - ``serialization_error`` field naming the cause (see #1452). + A record is never lost to a serialization error. If the full payload + cannot be serialized, it degrades to ``_JSON_CORE_FIELDS`` plus a + ``serialization_error`` field naming the cause, and finally to a + constant record. The guarantee is unconditional, not limited to the + failure modes anticipated here (see #1452). """ payload: dict[str, Any] = { "timestamp": self.formatTime(record, self.datefmt), @@ -165,24 +192,30 @@ def _format_json(self, record: logging.LogRecord) -> str: # structurally *before* `default` is consulted, and a value whose # `__str__` raises propagates out of `default` itself. Either one would # be swallowed by `Handler.handleError` and cost us the whole record, so - # fall back to the scalar fields — which cannot fail to serialize — and - # report the loss instead of hiding it. + # degrade in tiers instead, and report the loss rather than hide it. try: return json.dumps(payload, ensure_ascii=True, default=str) except Exception as exc: # noqa: BLE001 - never lose a record - safe = { - key: value - for key, value in payload.items() - if isinstance(value, (str, int, float, bool, type(None))) - } try: detail = f"{type(exc).__name__}: {exc}" except Exception: # noqa: BLE001 - the exception's own __str__ raised detail = type(exc).__name__ + + # Tier 2: the fields this formatter builds itself. Filtering the + # payload by scalar type is NOT enough — an `int` is a scalar and + # still fails above CPython's 4300-digit int/str conversion limit, + # so a large `correlation_id` would reproduce the same failure here + # and lose the record anyway. The optional enrichments are the only + # caller-supplied values in the payload, so drop them outright. + safe = {name: payload[name] for name in _JSON_CORE_FIELDS if name in payload} safe["serialization_error"] = detail - # No `default=`: `safe` holds only natively-encodable scalars, so - # this call cannot raise and the guarantee above is unconditional. - return json.dumps(safe, ensure_ascii=True) + try: + return json.dumps(safe, ensure_ascii=True) + except Exception: # noqa: BLE001 - a core field was also poisoned + # Tier 3: a constant. It cannot fail to serialize, so the + # "never lost" guarantee holds unconditionally rather than + # only for the failures anticipated above. + return _JSON_UNSERIALIZABLE_RECORD def formatException(self, ei) -> str: """Format exception with enhanced stack trace""" diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index fb3cd00f0..f1f9cb1f8 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -20,6 +20,8 @@ sys.path.insert(0, str(Path(__file__).resolve().parents[2] / "src")) from youtube_extension.backend.config.logging_config import ( # noqa: E402 + _JSON_CORE_FIELDS, + _JSON_UNSERIALIZABLE_RECORD, _UNSAFE_LOG_CHARS, StructuredFormatter, sanitize_log_record, @@ -429,3 +431,41 @@ def test_benign_json_record_has_no_serialization_error_field(): parsed = json.loads(buf.getvalue()) assert "serialization_error" not in parsed assert parsed["correlation_id"] == "req-42" + + +def test_oversized_int_enrichment_does_not_lose_the_record(): + # A scalar-type filter is not enough. `int` is a scalar, but CPython caps + # int->str conversion at 4300 digits, so a large `correlation_id` fails the + # *fallback* serialization too and the record is lost anyway. The fallback + # therefore keeps only the fields the formatter builds itself. + logger, buf = _make_json_logger("json-serialization-bigint") + logger.info("payload survives", extra={"request_id": 10**4400}) + + rendered = buf.getvalue() + assert rendered.strip(), "record was lost to the int/str conversion limit" + + parsed = json.loads(rendered) + assert parsed["level"] == "INFO" + assert parsed["message"] == "payload survives" + assert "serialization_error" in parsed + # The value that caused the failure must not be carried into the fallback. + assert "correlation_id" not in parsed + + +def test_fallback_drops_only_caller_supplied_enrichments(): + # The core fields are what make a degraded record still useful for routing + # and triage, so pin that they all survive rather than just `level`. + logger, buf = _make_json_logger("json-serialization-core-fields") + logger.info("still triageable", extra={"request_id": _ExplodingStr()}) + + parsed = json.loads(buf.getvalue()) + for field in _JSON_CORE_FIELDS: + assert field in parsed, f"core field {field!r} missing from fallback" + assert "correlation_id" not in parsed + + +def test_last_resort_record_cannot_itself_fail_to_serialize(): + # Tier 3 is what makes the guarantee unconditional rather than "covers the + # failures we thought of", so assert it is valid JSON and self-describing. + parsed = json.loads(_JSON_UNSERIALIZABLE_RECORD) + assert parsed["serialization_error"] From 1fa4f18ca136716839b1c6e4639735d5abf7048b Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:07:14 +0000 Subject: [PATCH 3/3] test(logging): exercise the last-resort tier through the real control path `test_last_resort_record_cannot_itself_fail_to_serialize` only parsed the constant. It never called `_format_json`, so it would have passed unchanged if the tier-3 `except` branch were deleted or made to re-raise -- a vacuous guard on the one branch that makes the "never lost" claim unconditional. Drive the real path instead: a filter poisons `process`, a *core* field that tier 2 retains by design, so both tiers fail and the sink must receive the constant record. Verified non-vacuous -- removing the tier-3 branch fails this test and only this test (1 failed, 28 passed). Raised by CodeRabbit on #1488. Closes #1452 --- tests/unit/test_logging_config_crlf.py | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index f1f9cb1f8..31464ae41 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -469,3 +469,25 @@ def test_last_resort_record_cannot_itself_fail_to_serialize(): # failures we thought of", so assert it is valid JSON and self-describing. parsed = json.loads(_JSON_UNSERIALIZABLE_RECORD) assert parsed["serialization_error"] + + +def test_last_resort_tier_is_reached_when_a_core_field_is_poisoned(): + # Parsing the constant alone would still pass if the tier-3 `except` were + # deleted, so drive the real control path: poison a *core* field, which + # tier 2 retains by design, and assert the sink gets the constant record. + logger, buf = _make_json_logger("json-serialization-last-resort") + + class _PoisonCoreField(logging.Filter): + def filter(self, record: logging.LogRecord) -> bool: + # `process` is in _JSON_CORE_FIELDS, so tier 2 cannot drop it. + record.process = 10**4400 + return True + + logger.addFilter(_PoisonCoreField()) + logger.info("tier 3") + + rendered = buf.getvalue() + assert rendered.strip(), "record was lost when both tiers failed" + assert rendered.strip() == _JSON_UNSERIALIZABLE_RECORD + assert len(rendered.splitlines()) == 1 + assert json.loads(rendered)["serialization_error"]