diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 2cb29f4c1..c93950038 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/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,47 @@ 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 retention filter for the serialization fallback (#1452). Two details + matter, and both are load-bearing: + + ``type(value) in``, not ``isinstance``: ``isinstance`` consults + ``value.__class__``, which an object can forge as a property returning + ``str``. Such a value passes an ``isinstance`` filter, reaches the fallback + ``json.dumps``, and raises — losing the record the fallback exists to save. + Exact runtime types cannot be forged. + + 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. + """ + if type(value) is float: + return math.isfinite(value) + return type(value) 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 entire + point is that the record survives. ``str(exc)`` is itself hostile there: + the exception can originate in a call site's own ``__str__``, so it may be + an instance of a class whose ``__str__`` raises too. + + The bare type name is the fallback because it is an attribute lookup rather + than a dunder call, so no call-site code runs to produce it. That is not the + same as "cannot raise" — a hostile *metaclass* could still make ``__name__`` + a raising property — but such a class cannot be reached from the enrichment + path this guards, which carries values, not exception classes. + """ + 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. @@ -162,18 +204,35 @@ def _format_json(self, record: logging.LogRecord) -> str: # 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 + # encodable scalars, so a bad enrichment costs its own value rather than # the whole record. + # + # `allow_nan=False` because Python's default emits the JavaScript + # literals `NaN`/`Infinity`, which are not valid JSON. A strict + # downstream parser rejects such a record — the same loss as dropping it + # here, only moved to the consumer where it is harder to diagnose. + # Raising instead routes it to the fallback, which drops the offending + # enrichment and keeps a record every parser accepts. + # + # 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. This is not a "no record is ever lost" + # guarantee; it is "serialization never loses one". 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) + # Cannot raise: `_is_json_safe_scalar` admits only values the + # encoder emits directly, so there is nothing for `default` to be + # consulted for and nothing left for `allow_nan` to reject. Passing + # `default=str` here would reinstate the raising-`__str__` hole. + return json.dumps(safe, ensure_ascii=True, allow_nan=False) 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 551bcf7df..47792fc6f 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -381,6 +381,107 @@ def test_serialization_fallback_still_escapes_attacker_content(): assert parsed["message"] == _FORGERY +# --------------------------------------------------------------------------- +# #1452 follow-up: the fallback added above is not self-sufficient either. +# +# Three inputs still cost the record — or its validity — after that fix: +# +# 1. a value that forges `__class__`, defeating the `isinstance` retention +# filter and reaching a `json.dumps` whose `default=str` then raises; +# 2. an exception whose own `__str__` raises, detonating the +# `f"{type(exc).__name__}: {exc}"` that builds `serialization_error`; +# 3. a non-finite float, which serializes to the bare JavaScript literals +# `NaN`/`Infinity` — accepted by Python's lenient `json.loads`, rejected +# by every strict downstream parser. +# +# All three fail on the pre-follow-up implementation. +# --------------------------------------------------------------------------- + + +class _ForgedClass: + """Forges `__class__` as `str`, so an `isinstance` filter admits it.""" + + @property # type: ignore[misc] + def __class__(self): # type: ignore[override] + return str + + def __str__(self) -> str: + raise RuntimeError("forged value exploded") + + +class _ExplodingExc(Exception): + """An exception whose own `__str__` raises, as one from `__str__` may.""" + + def __str__(self) -> str: + raise RuntimeError("exception str() exploded") + + +class _RaisesExplodingExc: + def __str__(self) -> str: + raise _ExplodingExc() + + +def _strict_loads(line: str) -> dict: + """Parse as a *strict* JSON consumer would — `NaN`/`Infinity` are errors.""" + + def _reject(constant: str): + raise ValueError(f"not valid JSON: {constant}") + + return json.loads(line, parse_constant=_reject) + + +def test_forged_class_value_does_not_cost_the_record(): + # `isinstance` consults `__class__`, which this value forges as `str`; an + # `isinstance`-based filter keeps it, and the fallback dump then raises. + records = _emit_three("json-forged-class", _ForgedClass()) + + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + assert poisoned["level"] == "INFO" + assert "correlation_id" not in poisoned + + +def test_exception_with_exploding_str_does_not_cost_the_record(): + # The fallback must describe the failure without re-detonating it. + records = _emit_three("json-exploding-exc", _RaisesExplodingExc()) + + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + assert poisoned["level"] == "INFO" + # Degrades to the type name alone rather than losing the record. + assert poisoned["serialization_error"] == "_ExplodingExc" + + +@pytest.mark.parametrize( + "value", [float("nan"), float("inf"), float("-inf")], ids=["nan", "inf", "-inf"] +) +def test_non_finite_enrichment_stays_strictly_valid_json(value): + logger, buf = _make_json_logger(f"json-non-finite-{value}") + logger.info("poisoned", extra={"performance_ms": value}) + + line = buf.getvalue().strip() + # Pre-fix this emits a bare `NaN` / `Infinity` literal and raises here. + parsed = _strict_loads(line) + + assert parsed["message"] == "poisoned" + assert parsed["level"] == "INFO" + # The non-finite value costs itself, not the record. + assert "performance_ms" not in parsed + assert parsed["serialization_error"].startswith("ValueError:") + + +def test_finite_float_enrichment_is_still_retained(): + # The non-finite guard must not cost well-behaved floats their value. + logger, buf = _make_json_logger("json-finite-float") + logger.info("healthy", extra={"performance_ms": 12.5}) + + parsed = _strict_loads(buf.getvalue().strip()) + assert parsed["performance_ms"] == 12.5 + assert "serialization_error" not in parsed + + @pytest.fixture def _restore_root_logging(): """`setup_logging` calls dictConfig, which mutates global logging state."""