fix(logging): close the three holes the #1452 fallback shipped with

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,57 @@ def sanitize_log_record(rendered: str) -> str:
     return rendered.translate(_UNSAFE_LOG_CHARS)
 
 
+# Last-resort record for the serialization fallback. A module-level constant,
+# so emitting it cannot itself fail — which is what lets the guarantee below be
+# stated without a qualifier.
+_JSON_UNSERIALIZABLE_RECORD = (
+    '{"serialization_error": "log record could not be serialized"}'
+)
+
+
+def _describe_exception(exc: BaseException) -> str:
+    """Name an exception without trusting its ``__str__``.
+
+    Used only by the serialization fallback, which exists precisely because a
+    hostile ``__str__`` can raise. Interpolating ``exc`` there unguarded
+    reintroduces that failure *inside the handler for it* — measured on
+    ``8517bf8`` at 2 of 3 records reaching the sink. The class name is a plain
+    attribute and is always renderable, so it is the safe floor.
+    """
+    try:
+        return f"{type(exc).__name__}: {exc}"
+    except Exception:  # noqa: BLE001 - the fallback must not need a fallback
+        return type(exc).__name__
+
+
+def _is_json_safe_scalar(value: object) -> bool:
+    """Is this a value ``json`` emits directly, with no ``default`` and no NaN?
+
+    The filter for the serialization fallback. That fallback's dump carries no
+    ``default=`` — anything reaching ``default`` there would reinstate the
+    raising-``__str__`` hole it exists to close — 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 dump,
+    and costs the record the fallback exists to save — measured on ``8517bf8``
+    at 2 of 3 records reaching the sink. ``json`` dispatches on the real
+    runtime type, which cannot be forged, so matching on it is what makes this
+    filter agree with the encoder rather than merely resemble it.
+
+    Non-finite floats are excluded. ``json`` renders them as the JavaScript
+    literals ``NaN``/``Infinity``, which are not valid JSON: a strict parser
+    rejects the record, so keeping the field loses the record downstream
+    instead of at the sink.
+    """
+    value_type = type(value)
+    if value_type is float:
+        return math.isfinite(value)
+    return value_type in (str, int, bool, type(None))
+
+
 class StructuredFormatter(logging.Formatter):
     """
     Custom formatter for structured logging with enhanced metadata.
@@ -164,16 +216,37 @@ def _format_json(self, record: logging.LogRecord) -> str:
         # 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.
+        # `allow_nan=False` on the *primary* dump is what routes a non-finite
+        # enrichment here rather than emitting `NaN`/`Infinity` — JavaScript
+        # literals that are not valid JSON, so a strict parser rejects the whole
+        # record. Losing it at the sink, where the fallback can degrade it into
+        # something parseable, beats losing it downstream where nothing can.
         try:
-            return json.dumps(payload, ensure_ascii=True, default=str)
+            return json.dumps(payload, ensure_ascii=True, default=str, allow_nan=False)
         except Exception as exc:  # noqa: BLE001 - never lose a record
+            # Three things make this retry unable to fail the way the first
+            # attempt did, and each closes a hole the retry shipped with:
+            #
+            #   * `_is_json_safe_scalar` matches the exact runtime type, so a
+            #     forged `__class__` cannot smuggle a raising `__str__` past it;
+            #   * `_describe_exception` renders `exc` without trusting its own
+            #     `__str__`;
+            #   * no `default=`, so nothing on this path can reach `str()` at
+            #     all — the filter has already excluded everything that would.
+            #
+            # `allow_nan=False` is belt-and-braces over the float check: it
+            # turns any non-finite that somehow survives into a raise caught
+            # below rather than a record no strict parser will accept.
             safe: dict[str, Any] = {
                 key: value
                 for key, value in payload.items()
-                if isinstance(value, (str, int, float, bool, type(None)))
+                if _is_json_safe_scalar(value)
             }
-            safe["serialization_error"] = f"{type(exc).__name__}: {exc}"
-            return json.dumps(safe, ensure_ascii=True, default=str)
+            safe["serialization_error"] = _describe_exception(exc)
+            try:
+                return json.dumps(safe, ensure_ascii=True, allow_nan=False)
+            except Exception:  # noqa: BLE001 - a constant is the floor
+                return _JSON_UNSERIALIZABLE_RECORD
 
     def formatException(self, ei) -> str:
         """Format exception with enhanced stack trace"""

tests/unit/test_logging_config_crlf.py

@@ -381,6 +381,121 @@ def test_serialization_fallback_still_escapes_attacker_content():
     assert parsed["message"] == _FORGERY
 
 
+# ---------------------------------------------------------------------------
+# #1452, second pass: the *fallback* shipped with the same class of hole it was
+# written to close — a step that can itself raise, inside the handler that
+# exists because raising is the failure mode.
+#
+# Three of them, each measured against `8517bf8` (the merged #1491) before
+# being fixed, using the same healthy → poisoned → healthy probe as above:
+#
+#   1. `isinstance(value, str)` consults `value.__class__`, which a property
+#      can forge. The value passes the filter, reaches a `json.dumps` that
+#      still had `default=str`, and its raising `__str__` kills the record.
+#      Measured: 2 of 3.
+#   2. `f"...{exc}"` renders the caught exception unguarded. An exception whose
+#      own `__str__` raises kills the record. Measured: 2 of 3.
+#   3. A non-finite float serializes to the bare literal `NaN`, which is not
+#      valid JSON. The record reaches the sink and is then rejected by any
+#      strict parser — lost downstream instead of at the sink.
+#
+# Every test below fails on `8517bf8`.
+# ---------------------------------------------------------------------------
+
+
+class _ForgedClass:
+    """`isinstance(v, str)` is True; `str(v)` raises. Exact-type checks see through it."""
+
+    @property
+    def __class__(self):  # noqa: ANN204 - forging the type is the point
+        return str
+
+    def __str__(self) -> str:
+        raise RuntimeError("forged str() exploded")
+
+
+class _UnrenderableExc(Exception):
+    """An exception that cannot be interpolated — `f"{exc}"` raises on it."""
+
+    def __str__(self) -> str:
+        raise RuntimeError("exc.__str__ exploded")
+
+
+class _RaisesUnrenderable:
+    def __str__(self) -> str:
+        raise _UnrenderableExc()
+
+
+def test_forged_class_cannot_smuggle_a_raising_str_into_the_fallback():
+    records = _emit_three("json-forged-class", _ForgedClass())
+
+    assert len(records) == 3
+    poisoned = records[1]
+    assert poisoned["message"] == "poisoned"
+    # The #1429 guarantee still holds on the degraded record.
+    assert poisoned["level"] == "INFO"
+    assert "correlation_id" not in poisoned
+    assert "serialization_error" in poisoned
+
+
+def test_unrenderable_exception_does_not_cost_the_record():
+    records = _emit_three("json-unrenderable-exc", _RaisesUnrenderable())
+
+    assert len(records) == 3
+    poisoned = records[1]
+    assert poisoned["message"] == "poisoned"
+    assert poisoned["level"] == "INFO"
+    assert "correlation_id" not in poisoned
+    # Degraded to the bare class name rather than "Name: message" — the class
+    # name is an attribute, so naming the exception cannot itself raise.
+    assert poisoned["serialization_error"] == "_UnrenderableExc"
+
+
+@pytest.mark.parametrize("poison", [float("nan"), float("inf"), float("-inf")])
+def test_non_finite_enrichment_still_yields_strictly_valid_json(poison):
+    logger, buf = _make_json_logger("json-non-finite")
+    logger.info("timing", extra={"request_id": poison})
+    line = buf.getvalue().strip()
+
+    # `json.loads` accepts `NaN`/`Infinity` by default, so asserting it parses
+    # would pass against the bug. `parse_constant` fires on exactly those
+    # literals, which is what a strict downstream parser rejects.
+    def _reject(literal: str) -> None:
+        raise AssertionError(f"non-finite literal reached the sink: {literal}")
+
+    parsed = json.loads(line, parse_constant=_reject)
+    assert parsed["level"] == "INFO"
+    assert parsed["message"] == "timing"
+    assert "correlation_id" not in parsed
+    assert parsed["serialization_error"].startswith("ValueError:")
+
+
+def test_fallback_of_last_resort_is_emitted_rather_than_nothing():
+    # The floor: if even the degraded dump fails, a constant is emitted. Drive
+    # it directly, since no `extra` value can defeat the scalar filter — that
+    # is the point of the filter, and the reason this needs a direct probe.
+    formatter = StructuredFormatter(datefmt="%Y-%m-%d %H:%M:%S", json_output=True)
+    record = logging.LogRecord(
+        "json-floor", logging.INFO, __file__, 1, "floored", None, None
+    )
+    formatter.format(record)  # populates service_name / version
+
+    original_dumps = json.dumps
+
+    def _always_raises(*args, **kwargs):
+        raise RuntimeError("even the degraded dump failed")
+
+    json.dumps = _always_raises
+    try:
+        rendered = formatter.format(record)
+    finally:
+        json.dumps = original_dumps
+
+    assert json.loads(rendered) == {
+        "serialization_error": "log record could not be serialized"
+    }
+
+
 @pytest.fixture
 def _restore_root_logging():
     """`setup_logging` calls dictConfig, which mutates global logging state."""