fix(logging): keep the record when a JSON enrichment cannot serialize

src/youtube_extension/backend/config/logging_config.py

@@ -10,6 +10,7 @@
 import json
 import logging
 import logging.config
+import math
 import os
 import sys
 from datetime import datetime
@@ -76,6 +77,48 @@ def sanitize_log_record(rendered: str) -> str:
     return rendered.translate(_UNSAFE_LOG_CHARS)
 
 
+def _is_json_safe_scalar(value: object) -> bool:
+    """Is this a value ``json.dumps`` emits directly, under ``allow_nan=False``?
+
+    The filter for the serialization fallback (#1452). The fallback's own dump
+    has no ``default=``, deliberately — anything reaching ``default`` there
+    would reinstate the raising-``__str__`` hole — so this filter is the only
+    thing standing between it and a second, fatal raise. It is exact about two
+    things:
+
+    ``type(value) is``, never ``isinstance``. ``isinstance`` consults
+    ``value.__class__``, which an object can forge with a property returning
+    ``str``. Such a value passes an ``isinstance`` filter, reaches the
+    ``default``-less dump, raises ``TypeError``, and costs the record the
+    fallback exists to save. ``json`` itself dispatches on the real runtime
+    type, which cannot be forged, so matching on it is what makes this filter
+    agree with the encoder. Credit to #1471 for catching this.
+
+    Non-finite floats are excluded: ``json`` renders them as the JavaScript
+    literals ``NaN``/``Infinity``, which are not valid JSON, so a strict
+    downstream parser would reject the whole record.
+    """
+    value_type = type(value)
+    if value_type is float:
+        return math.isfinite(value)
+    return value_type in (str, bool, int, type(None))
+
+
+def _describe_exception(exc: BaseException) -> str:
+    """Describe an exception without ever raising a second one.
+
+    Used on the JSON serialization fallback path (#1452), where the whole point
+    is that a record survives. ``str(exc)`` is itself attacker-adjacent there:
+    the exception can come from a call site's own ``__str__``, so it may be an
+    instance of a class whose ``__str__`` raises too. The type name is a plain
+    attribute lookup and is always safe.
+    """
+    try:
+        return f"{type(exc).__name__}: {exc}"
+    except Exception:  # noqa: BLE001 - the type name alone still identifies it
+        return type(exc).__name__
+
+
 class StructuredFormatter(logging.Formatter):
     """
     Custom formatter for structured logging with enhanced metadata.
@@ -156,10 +199,52 @@ 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 the common case — an `extra` value of a type
+        # `json` cannot natively encode — but it is NOT sufficient on its own,
+        # and the fallback below is what makes a payload always serializable
+        # (#1452). Three inputs defeat `default=str`:
+        #
+        #   * a circular container, which ``json.dumps`` rejects structurally
+        #     *before* ``default`` is ever consulted;
+        #   * a value whose ``__str__`` raises, where ``default`` is consulted
+        #     and the exception propagates straight back out of it;
+        #   * a non-finite float, which ``default`` is never consulted for
+        #     either — see ``allow_nan=False`` below.
+        #
+        # Each raises inside ``Handler.emit``, where ``logging`` swallows it via
+        # ``handleError`` and drops the record entirely. Only the optional
+        # enrichments can carry such a value, so the fallback keeps every
+        # JSON-safe scalar — including `level`, which downstream consumers route
+        # and alert on — and reports what was dropped.
+        #
+        # SCOPE: this covers *serializing* the payload. Building it can still
+        # raise upstream of here — ``record.getMessage()`` on mismatched
+        # ``%``-args is the reachable case — and that is out of scope because it
+        # fails the line-oriented path identically (``super().format()`` calls
+        # ``getMessage()`` too). This is not a "no record is ever lost"
+        # guarantee; it is a "serialization never loses one".
+        #
+        # ``allow_nan=False`` because Python's default emits the JavaScript
+        # literals ``NaN``/``Infinity``, which are not valid JSON. A strict
+        # downstream parser rejects the record — the same loss as dropping it
+        # here, just moved to the consumer where it is harder to see. Raising
+        # instead routes it to the fallback, which drops the offending
+        # enrichment and keeps a record every parser accepts.
+        try:
+            return json.dumps(
+                payload, ensure_ascii=True, allow_nan=False, default=str
+            )
+        except Exception as exc:  # noqa: BLE001 - a record is never worth losing
+            safe: dict[str, Any] = {
+                key: value
+                for key, value in payload.items()
+                if _is_json_safe_scalar(value)
+            }
+            safe["serialization_error"] = _describe_exception(exc)
+            # Cannot raise: `_is_json_safe_scalar` admits only values the
+            # encoder emits directly, and `allow_nan=False` has nothing left to
+            # reject because non-finite floats were filtered out above.
+            return json.dumps(safe, ensure_ascii=True, allow_nan=False)
 
     def formatException(self, ei) -> str:
         """Format exception with enhanced stack trace"""

tests/unit/test_logging_config_crlf.py

@@ -22,6 +22,7 @@
 from youtube_extension.backend.config.logging_config import (  # noqa: E402
     _UNSAFE_LOG_CHARS,
     StructuredFormatter,
+    _describe_exception,
     sanitize_log_record,
     setup_logging,
 )
@@ -309,6 +310,211 @@ def test_line_oriented_path_is_untouched_by_the_json_fix():
     assert buf.getvalue() == "INFO - all good video-123\n"
 
 
+# --- #1452: a record must survive an unserializable enrichment -------------
+#
+# `default=str` alone does not deliver "never lose a record". Both payloads
+# below raise out of `json.dumps`, inside `Handler.emit`, where `logging`
+# swallows the exception via `handleError` and drops the record silently.
+# `correlation_id` is the reachable field: it is populated from
+# `record.request_id`, which middleware may set to a framework object.
+
+
+class _ExplodingStr:
+    """A value whose ``__str__`` raises — `default=str` propagates it."""
+
+    def __str__(self) -> str:
+        raise RuntimeError("str() exploded")
+
+
+def _circular_container() -> dict:
+    """`json.dumps` rejects this structurally, before `default` is consulted."""
+    circular: dict = {}
+    circular["self"] = circular
+    return circular
+
+
+@pytest.mark.parametrize(
+    ("label", "poison"),
+    [
+        ("circular", _circular_container()),
+        ("exploding-str", _ExplodingStr()),
+    ],
+)
+def test_unserializable_enrichment_does_not_cost_the_record(label, poison):
+    logger, buf = _make_json_logger(f"json-unserializable-{label}")
+    logger.info("healthy before")
+    logger.info("poisoned record", extra={"request_id": poison})
+    logger.info("healthy after")
+
+    lines = [line for line in buf.getvalue().splitlines() if line.strip()]
+    # The pre-#1452 implementation emits 2 — the poisoned record is dropped.
+    assert len(lines) == 3
+
+    parsed = json.loads(lines[1])
+    # `level` stays authoritative, which is what downstream routing alerts on.
+    assert parsed["level"] == "INFO"
+    assert parsed["message"] == "poisoned record"
+    # The unserializable enrichment is dropped, and says so rather than
+    # vanishing silently.
+    assert "correlation_id" not in parsed
+    assert "serialization_error" in parsed
+
+
+def test_serialization_fallback_keeps_the_record_a_single_json_line():
+    # The fallback must honour the same two guarantees as the happy path:
+    # one physical line, and no forged field from attacker content.
+    logger, buf = _make_json_logger("json-unserializable-forgery")
+    logger.info(_FORGERY, extra={"request_id": _ExplodingStr()})
+
+    rendered = buf.getvalue()
+    assert rendered.count("\n") == 1
+    parsed = json.loads(rendered)
+
+    assert parsed["level"] == "INFO"
+    assert "forged" not in parsed
+    assert parsed["message"] == _FORGERY
+
+
+def test_benign_enrichments_still_reach_the_json_record():
+    # The fallback must not fire on serializable values — a scalar
+    # `correlation_id` still rides through the normal path.
+    logger, buf = _make_json_logger("json-benign-enrichment")
+    logger.info("fine", extra={"request_id": "req-123"})
+    parsed = json.loads(buf.getvalue())
+
+    assert parsed["correlation_id"] == "req-123"
+    assert "serialization_error" not in parsed
+
+
+class _ForgedClassStr:
+    """A value that lies about its type *and* raises from `__str__`.
+
+    `isinstance(x, str)` consults `x.__class__`, which this forges. It
+    therefore passes an `isinstance`-based scalar filter, reaches the
+    fallback's `default`-less `json.dumps`, and raises `TypeError` — losing the
+    record the fallback exists to save. `json` dispatches on the real runtime
+    type, so `type(value) is` agrees with the encoder and `isinstance` does not.
+    """
+
+    @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) is ...` over `isinstance(...)` in _is_json_safe_scalar.
+    # With the isinstance form this value is retained and the record is dropped.
+    logger, buf = _make_json_logger("json-forged-class")
+    logger.info("before")
+    logger.info("survives a liar", extra={"request_id": _ForgedClassStr()})
+    logger.info("after")
+
+    messages = [
+        json.loads(line)["message"]
+        for line in buf.getvalue().splitlines()
+        if line.strip()
+    ]
+    assert messages == ["before", "survives a liar", "after"]
+
+    parsed = json.loads(buf.getvalue().splitlines()[1])
+    assert parsed["level"] == "INFO"
+    assert "correlation_id" not in parsed
+    assert parsed["serialization_error"].startswith("RuntimeError")
+
+
+@pytest.mark.parametrize("value", [float("inf"), float("-inf"), float("nan")])
+def test_non_finite_enrichment_does_not_produce_invalid_json(value):
+    # Python's json emits the JavaScript literals NaN/Infinity for these, which
+    # are not valid JSON — a strict downstream parser rejects the whole record,
+    # which is the same loss as dropping it, moved to the consumer. `json.loads`
+    # accepts them by default, so this asserts against a *strict* parse.
+    logger, buf = _make_json_logger(f"json-non-finite-{value}")
+    logger.info("measured", extra={"request_id": value})
+
+    rendered = buf.getvalue()
+
+    def _reject(constant: str) -> None:
+        raise AssertionError(f"non-JSON constant in record: {constant}")
+
+    parsed = json.loads(rendered, parse_constant=_reject)
+    assert parsed["level"] == "INFO"
+    assert parsed["message"] == "measured"
+    assert "correlation_id" not in parsed
+    assert "serialization_error" in parsed
+
+
+def test_finite_float_enrichment_is_kept():
+    # The non-finite guard must not cost ordinary numeric enrichments.
+    logger, buf = _make_json_logger("json-finite-float")
+    logger.info("measured", extra={"request_id": 12.5})
+    parsed = json.loads(buf.getvalue())
+
+    assert parsed["correlation_id"] == 12.5
+    assert "serialization_error" not in parsed
+
+
+class _ExplodingError(Exception):
+    """An exception whose own `__str__` raises."""
+
+    def __str__(self) -> str:
+        raise RuntimeError("the error's own __str__ exploded")
+
+
+class _NestedExplodingStr:
+    """`__str__` raises an exception that itself raises when rendered.
+
+    This is what makes `_describe_exception`'s inner guard live code rather
+    than defensive decoration: the fallback renders the exception it caught,
+    and here that render raises again.
+    """
+
+    def __str__(self) -> str:
+        raise _ExplodingError()
+
+
+def test_exception_whose_str_also_raises_does_not_lose_the_record():
+    # Credit to #1471/#1472 for exercising this end-to-end; the helper's own
+    # unit test above cannot show the path is reachable through the formatter.
+    logger, buf = _make_json_logger("json-nested-exploding")
+    logger.info("still emitted", extra={"request_id": _NestedExplodingStr()})
+
+    lines = [line for line in buf.getvalue().splitlines() if line.strip()]
+    assert len(lines) == 1, "the nested-raise path dropped the record"
+
+    parsed = json.loads(lines[0])
+    assert parsed["level"] == "INFO"
+    assert parsed["message"] == "still emitted"
+    # The type name is still reportable even when rendering the value is not.
+    assert parsed["serialization_error"] == "_ExplodingError"
+
+
+def test_rendered_traceback_survives_the_serialization_fallback():
+    # `exception` is rendered to `str` before the guarded dump, so a failing
+    # enrichment must not also cost us the traceback.
+    logger, buf = _make_json_logger("json-fallback-traceback")
+    try:
+        raise ValueError("the real cause")
+    except ValueError:
+        logger.error("failed", exc_info=True, extra={"request_id": _ExplodingStr()})
+
+    parsed = json.loads(buf.getvalue())
+    assert "serialization_error" in parsed  # the fallback did fire
+    assert "the real cause" in parsed["exception"]  # ...and kept the traceback
+
+
+def test_describe_exception_survives_an_exception_that_cannot_be_stringified():
+    # The fallback formats the error it caught. If that exception's own
+    # __str__ raises, describing it must not re-raise and re-lose the record.
+    class _Unprintable(Exception):
+        def __str__(self) -> str:
+            raise RuntimeError("nested boom")
+
+    assert _describe_exception(_Unprintable()) == "_Unprintable"
+
+
 @pytest.fixture
 def _restore_root_logging():
     """`setup_logging` calls dictConfig, which mutates global logging state."""