fix(logging): keep the record when JSON serialization raises

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"""

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."""