diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..2cb29f4c1 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -156,10 +156,24 @@ 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` coerces values `json` cannot natively encode, but it is + # not sufficient on its own to keep a record alive: a circular container + # is rejected structurally *before* `default` is consulted, and a value + # whose `__str__` raises propagates straight out of `default`. Either + # way `logging` swallows the raise via `Handler.handleError` and drops + # the record. The fallback below re-serializes with only the natively + # encodable fields, so a bad enrichment costs its own value rather than + # the whole record. + try: + return json.dumps(payload, ensure_ascii=True, default=str) + except Exception as exc: # noqa: BLE001 - never lose a record + safe: dict[str, Any] = { + key: value + for key, value in payload.items() + if isinstance(value, (str, int, float, bool, type(None))) + } + safe["serialization_error"] = f"{type(exc).__name__}: {exc}" + return json.dumps(safe, ensure_ascii=True, default=str) 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..551bcf7df 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -309,6 +309,78 @@ def test_line_oriented_path_is_untouched_by_the_json_fix(): assert buf.getvalue() == "INFO - all good video-123\n" +# --------------------------------------------------------------------------- +# #1452: `default=str` alone does not keep a record alive. +# +# `default` is consulted only for values `json` cannot natively encode, and it +# is called unguarded. Two inputs defeat it, and both cost the *whole record* +# because `logging` swallows the raise via `Handler.handleError`: +# +# 1. a circular container — rejected structurally before `default` is reached; +# 2. a value whose `__str__` raises — the exception propagates out of `default`. +# +# Reachable through the `correlation_id` / `performance_ms` enrichment loop, +# which #1439 introduced. Both tests fail on the pre-#1452 implementation. +# --------------------------------------------------------------------------- + + +class _ExplodingStr: + """An `extra` value whose `__str__` raises — walks straight through `default=str`.""" + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _emit_three(name: str, poison: object) -> list[dict]: + """Log healthy → poisoned → healthy, and return every record that survived.""" + logger, buf = _make_json_logger(name) + logger.info("healthy one") + logger.info("poisoned", extra={"request_id": poison}) + logger.info("after poison") + return [json.loads(line) for line in buf.getvalue().splitlines() if line.strip()] + + +def test_circular_correlation_id_does_not_cost_the_record(): + circular: dict = {} + circular["self"] = circular + + records = _emit_three("json-circular", circular) + + # Pre-fix this is 2 of 3 — the poisoned record never reaches the sink. + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + # The security property still holds: level is authoritative, not forged. + assert poisoned["level"] == "INFO" + # The bad value costs itself, and says why. + assert "correlation_id" not in poisoned + assert poisoned["serialization_error"].startswith("ValueError:") + + +def test_exploding_str_correlation_id_does_not_cost_the_record(): + records = _emit_three("json-exploding-str", _ExplodingStr()) + + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + assert poisoned["level"] == "INFO" + assert "correlation_id" not in poisoned + # A narrow `except (TypeError, ValueError, RecursionError)` would miss this. + assert poisoned["serialization_error"] == "RuntimeError: str() exploded" + + +def test_serialization_fallback_still_escapes_attacker_content(): + # The fallback must not become a hole in the #1429 fix: a forgery payload + # in `message` has to stay escaped on the degraded path too. + logger, buf = _make_json_logger("json-fallback-escaping") + logger.info(_FORGERY, extra={"request_id": _ExplodingStr()}) + parsed = json.loads(buf.getvalue()) + + 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."""