diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..18201828c 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -156,10 +156,40 @@ 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. + # + # `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 + 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 type(value) in {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..8e7f39c8f 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -309,6 +309,122 @@ 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) + + +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. + 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."""