fix(logging): close three ways the JSON fallback still lost the record

src/youtube_extension/backend/config/logging_config.py

@@ -10,11 +10,12 @@
 import json
 import logging
 import logging.config
+import math
 import os
 import sys
 from datetime import datetime
 from pathlib import Path
-from typing import Any
+from typing import Any, cast
 
 # Characters that can be abused to forge or corrupt log records (CWE-117 log
 # injection). Any of these in dynamic content — a log message, an ``exc_info``
@@ -76,6 +77,83 @@ def sanitize_log_record(rendered: str) -> str:
     return rendered.translate(_UNSAFE_LOG_CHARS)
 
 
+# Last-resort record for the JSON serialization fallback. A module constant of
+# pre-validated JSON, so emitting it involves no encoding step that could fail.
+_JSON_UNSERIALIZABLE_RECORD = (
+    '{"serialization_error": "log record could not be serialized"}'
+)
+
+
+def _int_is_json_safe(value: int) -> bool:
+    """Can ``json`` render this int without tripping CPython's digit cap?
+
+    ``json`` renders ints via ``str``, and CPython 3.11+ refuses int-to-str
+    conversion beyond ``sys.get_int_max_str_digits()`` (4300 by default). An
+    oversized int is therefore *a scalar that still raises*, which is why a
+    plain type check is not sufficient on the fallback path.
+
+    ``bit_length`` is used rather than attempting the conversion, because the
+    conversion is the operation being guarded against. ``log10(2) ≈ 0.30103``,
+    rounded up so the estimate can never understate the digit count.
+    """
+    get_limit = getattr(sys, "get_int_max_str_digits", None)
+    if get_limit is None:  # Python < 3.11 has no cap.
+        return True
+    limit = int(get_limit())
+    if limit <= 0:  # 0 disables the cap.
+        return True
+    return value.bit_length() * 0.302 + 1 < limit
+
+
+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 dump has
+    no ``default=`` — 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 three 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 raises — costing the record the fallback exists to save. ``json``
+    dispatches on the real runtime type, which cannot be forged, so matching on
+    it is what makes this filter agree with the encoder.
+
+    Non-finite floats are excluded: ``json`` renders them as the JavaScript
+    literals ``NaN``/``Infinity``, which are not valid JSON, so a strict
+    downstream parser rejects the whole record — the same loss as dropping it,
+    moved to the consumer where it is harder to see.
+
+    Oversized ints are excluded per ``_int_is_json_safe``.
+    """
+    value_type = type(value)
+    # `cast` rather than `isinstance` narrowing: the exact-type check above is
+    # the whole point of this filter, and `isinstance` is what it exists to
+    # avoid. The cast is sound precisely because `type(value) is` already
+    # established the runtime type.
+    if value_type is float:
+        return math.isfinite(cast(float, value))
+    if value_type is int:
+        return _int_is_json_safe(cast(int, value))
+    return value_type in (str, bool, type(None))
+
+
+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. The exception caught there may *be* one
+    raised from a call site's own ``__str__``, so interpolating ``exc`` can
+    raise a second time — inside the handler for the first. The type name is a
+    plain attribute lookup and is always safe.
+    """
+    try:
+        return f"{type(exc).__name__}: {exc}"
+    except Exception:  # noqa: BLE001 - the fallback must not need a fallback
+        return type(exc).__name__
+
+
 class StructuredFormatter(logging.Formatter):
     """
     Custom formatter for structured logging with enhanced metadata.
@@ -164,16 +242,48 @@ 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.
+        #
+        # The fallback must not be able to raise, or it loses the record for the
+        # same reason one level down. Three inputs defeated the first version of
+        # it, each measured against a real handler rather than reasoned about:
+        #
+        #   * an exception whose own `__str__` raises — the fallback rendered
+        #     the caught exception directly, so describing the failure became
+        #     the failure. Now via `_describe_exception`.
+        #   * a value forging `__class__ = str` — passed the `isinstance`
+        #     filter, then raised in the dump. Now excluded by matching on the
+        #     real runtime type.
+        #   * an int past CPython's 4300-digit `int`->`str` cap — a scalar by
+        #     every type test, and still fatal. Now excluded by magnitude.
+        #
+        # `allow_nan=False` because Python's default emits the JavaScript
+        # literals `NaN`/`Infinity`, which are not valid JSON. Raising instead
+        # routes the record to the fallback, which drops the offending
+        # enrichment and keeps a record every parser accepts.
+        #
+        # SCOPE, stated precisely because the bug this fixes was a comment
+        # claiming more than its code enforced: this guards *serializing* the
+        # payload. Building it can still raise above here — `record.getMessage()`
+        # on mismatched %-args is the reachable case — and that is out of scope
+        # because it fails the line-oriented path identically.
         try:
-            return json.dumps(payload, ensure_ascii=True, default=str)
+            return json.dumps(payload, ensure_ascii=True, allow_nan=False, 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)))
+                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 - the guarantee stays unconditional
+                # Not reachable through any input identified above: every value
+                # in `safe` is one the encoder emits directly. It is here so the
+                # guarantee is a property of the code rather than of the failure
+                # modes that happened to be anticipated — which is the exact
+                # gap #1452 was filed about.
+                return _JSON_UNSERIALIZABLE_RECORD
 
     def formatException(self, ei) -> str:
         """Format exception with enhanced stack trace"""

tests/unit/test_logging_config_crlf.py

@@ -20,8 +20,10 @@
 sys.path.insert(0, str(Path(__file__).resolve().parents[2] / "src"))
 
 from youtube_extension.backend.config.logging_config import (  # noqa: E402
+    _JSON_UNSERIALIZABLE_RECORD,
     _UNSAFE_LOG_CHARS,
     StructuredFormatter,
+    _describe_exception,
     sanitize_log_record,
     setup_logging,
 )
@@ -381,6 +383,145 @@ def test_serialization_fallback_still_escapes_attacker_content():
     assert parsed["message"] == _FORGERY
 
 
+# ---------------------------------------------------------------------------
+# #1452 follow-up: the fallback itself could still lose the record.
+#
+# The first fix wrapped the dump but left the *recovery* path able to raise, so
+# it kept the guarantee only for the two inputs it was written against. Each
+# case below was measured against a real handler on the merged implementation
+# (#1491) and dropped the record — the same "comment claims more than the code
+# enforces" gap that #1452 was filed about, one level down.
+# ---------------------------------------------------------------------------
+
+
+class _NastyError(Exception):
+    """An exception whose own `__str__` raises."""
+
+    def __str__(self) -> str:
+        raise RuntimeError("even the error explodes")
+
+
+class _RaisesNasty:
+    """`__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 _NastyError()
+
+
+class _ForgedClassStr:
+    """A value that lies about its type *and* raises from `__str__`.
+
+    `isinstance(x, str)` consults `x.__class__`, which this forges, so it
+    passes an `isinstance`-based scalar filter. `json` dispatches on the real
+    runtime type, so the value then raises inside the fallback's own dump —
+    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_exception_whose_str_also_raises_does_not_cost_the_record():
+    # Pre-fix: the fallback built `f"{type(exc).__name__}: {exc}"` directly, so
+    # describing the failure *became* the failure and the record was dropped.
+    records = _emit_three("json-nested-exploding", _RaisesNasty())
+
+    assert len(records) == 3
+    poisoned = records[1]
+    assert poisoned["level"] == "INFO"
+    assert poisoned["message"] == "poisoned"
+    # Degraded to the bare class name rather than "Name: message".
+    assert poisoned["serialization_error"] == "_NastyError"
+
+
+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 lost.
+    records = _emit_three("json-forged-class", _ForgedClassStr())
+
+    assert len(records) == 3
+    poisoned = records[1]
+    assert poisoned["level"] == "INFO"
+    assert poisoned["message"] == "poisoned"
+    assert "correlation_id" not in poisoned
+    assert poisoned["serialization_error"].startswith("RuntimeError:")
+
+
+def test_oversized_int_enrichment_does_not_cost_the_record():
+    # A scalar type test is not enough on its own. `int` is a scalar by every
+    # such test, but CPython caps int->str conversion at 4300 digits and `json`
+    # renders ints through `str`, so a large `correlation_id` raises inside the
+    # fallback too and the record is lost anyway.
+    records = _emit_three("json-oversized-int", 10**4400)
+
+    assert len(records) == 3
+    poisoned = records[1]
+    assert poisoned["level"] == "INFO"
+    assert poisoned["message"] == "poisoned"
+    assert "correlation_id" not in poisoned
+    assert poisoned["serialization_error"].startswith("ValueError:")
+
+
+def test_int_within_the_conversion_limit_is_still_kept():
+    # The magnitude guard must not cost ordinary integer enrichments.
+    logger, buf = _make_json_logger("json-ordinary-int")
+    logger.info("fine", extra={"request_id": 1234567890})
+    parsed = json.loads(buf.getvalue())
+
+    assert parsed["correlation_id"] == 1234567890
+    assert "serialization_error" not in parsed
+
+
+@pytest.mark.parametrize("value", [float("nan"), float("inf"), float("-inf")])
+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})
+
+    def _reject(constant: str) -> None:
+        raise AssertionError(f"non-JSON constant in record: {constant}")
+
+    parsed = json.loads(buf.getvalue(), 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={"performance_ms": 12.5})
+    parsed = json.loads(buf.getvalue())
+
+    assert parsed["performance_ms"] == 12.5
+    assert "serialization_error" not in parsed
+
+
+def test_last_resort_record_is_pre_validated_json():
+    # Tier 3 is what makes the guarantee a property of the code rather than of
+    # the failure modes that happened to be anticipated, so pin that emitting
+    # it involves no encoding step that could itself fail.
+    parsed = json.loads(_JSON_UNSERIALIZABLE_RECORD)
+    assert parsed["serialization_error"]
+
+
+def test_describe_exception_survives_an_exception_that_cannot_be_stringified():
+    assert _describe_exception(_NastyError()) == "_NastyError"
+
+
 @pytest.fixture
 def _restore_root_logging():
     """`setup_logging` calls dictConfig, which mutates global logging state."""