From e2393fec9f8cfcdc9d61b4f747ad78e5000d5c33 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 20:52:26 +0000 Subject: [PATCH 1/2] fix(logging): keep the record when JSON serialization raises Closes #1452 `_format_json` claimed `default=str` meant "a record is never lost to a serialization error". It does not. `default` is consulted only for values `json` cannot natively encode, and it is called unguarded, so two inputs still escape `json.dumps`: - a circular container is rejected structurally *before* `default` is consulted, so `default=str` never sees it; - a value whose `__str__` raises propagates out of `default` itself. Either way `logging` swallows the raise via `Handler.handleError` and drops the record. Measured on `main` with three `logger.info` calls through a real StreamHandler, the middle one poisoned: 2 of 3 records reached the sink, in both cases. With this change, 3 of 3. Reachable through `extra={"request_id": ...}`, which `format()` copies to `correlation_id` and the enrichment loop pulls into the payload. Not a regression -- the pre-#1439 `json_format` template never referenced `correlation_id`, so the input was unreachable on the JSON path before it -- and not reachable from request content, since headers arrive as strings and strings serialize correctly. Low severity: a robustness gap plus a comment that promised more than the code delivered. The fallback retains only natively-serializable scalars, which is every field except the two optional enrichments the call site controls, and records the cause in `serialization_error` rather than dropping it silently. It re-serializes with `json.dumps`, so the CWE-117 property from #1429 holds on this path too -- covered by a test rather than assumed. `except Exception`, not `(TypeError, ValueError, RecursionError)`: the narrow tuple looks more correct and misses the exploding-`__str__` case outright (verified -- it raises RuntimeError). The error-detail string is guarded too, for an exception whose own `__str__` raises. Verification (measured, not inferred): - `tests/unit/test_logging_config_crlf.py`: 24 passed. - Non-vacuous: against `main`'s `_format_json`, all 4 new tests fail (`4 failed, 20 passed`). The 20 pre-existing tests pass either way, so the line-oriented path and the #1429 fix are untouched. - `ruff check src/youtube_extension/backend/ src/youtube_extension/main.py` run exactly as CI does: `Found 2 errors` before and after -- byte-identical, both pre-existing. Clean on both changed files. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01GpTcrsgVsqbGV8dmPZadoe --- .../backend/config/logging_config.py | 29 ++++++- tests/unit/test_logging_config_crlf.py | 82 +++++++++++++++++++ 2 files changed, 107 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..82675ddd4 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -156,10 +156,31 @@ 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 and must not be described as if it were: + # a circular container is rejected structurally *before* `default` is + # consulted, and a value whose `__str__` raises propagates out of + # `default` itself. Either escapes `json.dumps`, and `logging` then + # swallows it via `Handler.handleError` and drops the record entirely. + # + # The fallback keeps the record instead. Only natively-serializable + # scalars are retained, which is every field above except the optional + # `performance_ms` / `correlation_id` enrichments -- the two the call + # site controls, and so the only ones that can carry the poison. + try: + return json.dumps(payload, ensure_ascii=True, default=str) + except Exception as exc: # noqa: BLE001 - never lose a record + try: + detail = f"{type(exc).__name__}: {exc}" + except Exception: # noqa: BLE001 - its `__str__` raises too + detail = type(exc).__name__ + safe = { + key: value + for key, value in payload.items() + if isinstance(value, (str, int, float, bool, type(None))) + } + safe["serialization_error"] = detail + 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..e45c49fa6 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -309,6 +309,88 @@ def test_line_oriented_path_is_untouched_by_the_json_fix(): assert buf.getvalue() == "INFO - all good video-123\n" +class _ExplodingStr: + """An `extra` value whose `__str__` raises. + + `json.dumps(default=str)` *does* consult `default` for this type, and the + exception then propagates out of `default` itself. + """ + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _circular_container() -> dict: + """A container `json.dumps` rejects structurally. + + The cycle is detected *before* `default` is consulted, so `default=str` + never sees it. This is the case a narrow `except (TypeError, ...)` around + the dump would appear to cover and does not. + """ + circular: dict = {} + circular["self"] = circular + return circular + + +@pytest.mark.parametrize( + "poison, expected_error", + [ + (_circular_container(), "ValueError"), + (_ExplodingStr(), "RuntimeError"), + ], + ids=["circular-container", "exploding-str"], +) +def test_unserializable_enrichment_does_not_cost_the_record(poison, expected_error): + # #1452: `default=str` alone loses the record for both of these. `logging` + # swallows the raise via `Handler.handleError`, so the failure is silent -- + # the record simply never reaches the sink. + logger, buf = _make_json_logger(f"json-unserializable-{expected_error}") + logger.info("still emitted", extra={"request_id": poison}) + + rendered = buf.getvalue() + assert rendered.strip(), "the record was dropped entirely" + parsed = json.loads(rendered) + + # The record survives with its authoritative metadata intact... + assert parsed["level"] == "INFO" + assert parsed["message"] == "still emitted" + # ...the poisoned enrichment is dropped rather than taking the record with + # it, and the reason is recorded rather than silently swallowed. + assert "correlation_id" not in parsed + assert parsed["serialization_error"].startswith(expected_error) + + +def test_a_poisoned_record_does_not_break_the_stream(): + # The blast radius that matters: `handleError` drops only the offending + # record, so a regression here is invisible unless you count what arrives. + logger, buf = _make_json_logger("json-unserializable-stream") + logger.info("before") + logger.info("poisoned", extra={"request_id": _ExplodingStr()}) + logger.info("after") + + messages = [ + json.loads(line)["message"] + for line in buf.getvalue().splitlines() + if line.strip() + ] + assert messages == ["before", "poisoned", "after"] + + +def test_fallback_record_still_holds_the_cwe_117_property(): + # The fallback must not become a hole in #1429: it re-serializes with + # `json.dumps`, so the forgery payload stays a value on this path too. + logger, buf = _make_json_logger("json-unserializable-forgery") + logger.info(_FORGERY, extra={"request_id": _ExplodingStr()}) + + rendered = buf.getvalue() + assert len(rendered.splitlines()) == 1, "fallback split the record" + parsed = json.loads(rendered) + + assert parsed["level"] == "INFO" + assert "forged" not in parsed + assert parsed["message"] == _FORGERY + + @pytest.fixture def _restore_root_logging(): """`setup_logging` calls dictConfig, which mutates global logging state.""" From 5887e3ce60f863214a3f54fbcabff0130d530114 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 20:57:03 +0000 Subject: [PATCH 2/2] fix(logging): use exact types in the fallback scalar filter Addresses CodeRabbit's blocking finding on #1471. The fallback filtered with `isinstance(value, (str, int, float, bool, type(None)))`. `isinstance` consults `value.__class__`, which an object can forge as a property returning `str`. Such a value passes the filter, reaches the fallback's `json.dumps` -- which deliberately has no `default=` -- and raises `TypeError`. The record is lost, which is the exact failure the fallback exists to prevent. Verified rather than taken on trust: isinstance(o, str) : True type(o) in {str, ...} : False first dumps : raised RuntimeError (fallback triggers) retained by isinstance : ['level', 'correlation_id'] second dumps (isinstance) : raised TypeError -> RECORD LOST retained by exact type : ['level'] second dumps (exact type) : {"level": "INFO"} `type(value) in {...}` cannot be forged, so it enforces the invariant the comment already claimed -- "only natively-serializable scalars are retained" -- rather than asserting it. That is the same defect class this PR is about: a guard whose stated guarantee the code did not deliver. Adding `default=str` to the fallback dump would also stop the TypeError, and is the wrong fix: it reinstates the raising-`__str__` hole the first dump already demonstrated. Nothing may reach `default` on the fallback path. `except Exception` is unchanged and stays correct -- it excludes `BaseException` subclasses such as `KeyboardInterrupt` and `SystemExit`. Verification: - `tests/unit/test_logging_config_crlf.py`: 25 passed (was 24). - Non-vacuous, and precisely so: reverting only the filter line to the `isinstance` form fails exactly `test_fallback_filter_is_not_fooled_by_a_ forged_class` and nothing else. - `ruff` clean on both changed files; the CI invocation reports the same 2 pre-existing errors as `main`. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01GpTcrsgVsqbGV8dmPZadoe --- .../backend/config/logging_config.py | 11 +++++- tests/unit/test_logging_config_crlf.py | 34 +++++++++++++++++++ 2 files changed, 44 insertions(+), 1 deletion(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 82675ddd4..18201828c 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -167,6 +167,15 @@ def _format_json(self, record: logging.LogRecord) -> str: # scalars are retained, which is every field above except the optional # `performance_ms` / `correlation_id` enrichments -- the two the call # site controls, and so the only ones that can carry the poison. + # + # `type(value) in ...`, not `isinstance`: `isinstance` consults + # `value.__class__`, which an object can forge as a property returning + # `str`. Such a value passes the filter, reaches a `json.dumps` with no + # `default` to fall back on, and raises `TypeError` -- losing the record + # the fallback exists to save. Exact runtime types cannot be forged, so + # this enforces the invariant the comment claims rather than asserting + # it. Adding `default=str` here instead would reinstate the raising + # `__str__` hole; nothing may reach `default` on this path. try: return json.dumps(payload, ensure_ascii=True, default=str) except Exception as exc: # noqa: BLE001 - never lose a record @@ -177,7 +186,7 @@ def _format_json(self, record: logging.LogRecord) -> str: safe = { key: value for key, value in payload.items() - if isinstance(value, (str, int, float, bool, type(None))) + if type(value) in {str, int, float, bool, type(None)} } safe["serialization_error"] = detail return json.dumps(safe, ensure_ascii=True) diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index e45c49fa6..8e7f39c8f 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -360,6 +360,40 @@ def test_unserializable_enrichment_does_not_cost_the_record(poison, expected_err assert parsed["serialization_error"].startswith(expected_error) +class _ForgedClassStr: + """An `extra` value that lies about its type *and* raises from `__str__`. + + `isinstance(x, str)` consults `x.__class__`, so this passes a scalar filter + written with `isinstance`. `json.dumps` uses the real runtime type, so the + fallback's own dump then raises `TypeError` with no `default` to catch it -- + losing the record the fallback exists to save. + """ + + @property + def __class__(self): # type: ignore[override] + return str + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def test_fallback_filter_is_not_fooled_by_a_forged_class(): + # Pins `type(value) in {...}` over `isinstance(...)`. With the isinstance + # form this value is retained, the fallback's `json.dumps` raises TypeError, + # and the record is dropped -- the exact failure the fallback prevents. + logger, buf = _make_json_logger("json-forged-class") + logger.info("survives a liar", extra={"request_id": _ForgedClassStr()}) + + rendered = buf.getvalue() + assert rendered.strip(), "the record was dropped entirely" + parsed = json.loads(rendered) + + assert parsed["level"] == "INFO" + assert parsed["message"] == "survives a liar" + assert "correlation_id" not in parsed + assert parsed["serialization_error"].startswith("RuntimeError") + + def test_a_poisoned_record_does_not_break_the_stream(): # The blast radius that matters: `handleError` drops only the offending # record, so a regression here is invisible unless you count what arrives.