From 7358509004a13863c800dfdf9b2a69e866bbfb30 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:10:30 +0000 Subject: [PATCH] fix(logging): close the three holes the #1452 fallback shipped with #1491 landed the #1452 fallback: when `json.dumps` raises, re-serialize from the scalar fields so a bad enrichment costs its own value rather than the whole record. The retry itself contains three steps that can raise -- inside the handler that exists because raising is the failure mode. Measured against 8517bf8 with a healthy -> poisoned -> healthy probe: 1. `isinstance(value, str)` consults `value.__class__`, which a property can forge. The value passes the filter, reaches a `json.dumps` that still carried `default=str`, and its raising `__str__` kills the record. 2 of 3 records reach the sink. 2. `f"{type(exc).__name__}: {exc}"` renders the caught exception unguarded. An exception whose own `__str__` raises kills the record. 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, where nothing can degrade it, instead of at the sink, where the fallback can. `_is_json_safe_scalar` matches the exact runtime type, which cannot be forged and is what `json` itself dispatches on, and excludes non-finite floats. `_describe_exception` names an exception without trusting its `__str__`. The retry drops `default=` entirely, so nothing on that path can reach `str()`; the filter has already excluded everything that would. `allow_nan=False` on the primary dump is what routes a non-finite enrichment to the fallback rather than emitting an unparseable record. A module-level constant is the floor, so the guarantee holds without a qualifier. Consolidates the residual findings from six competing pull requests against #1452 (#1471, #1472, #1477, #1488, #1493, #1494), each of which caught a different subset. Credit to #1471/#1477 for the forged-`__class__` hole, #1477 for the non-finite case, #1493/#1494 for the exception rendering, and #1488 for the constant floor. Verification: 29 passed in tests/unit/test_logging_config_crlf.py. Reverting only logging_config.py fails exactly the 6 new tests and no others (6 failed, 23 passed), so they are non-vacuous and scoped. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01DDs1q8Pw4i5y3wbBSaUf8V --- .../backend/config/logging_config.py | 81 +++++++++++- tests/unit/test_logging_config_crlf.py | 115 ++++++++++++++++++ 2 files changed, 192 insertions(+), 4 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 2cb29f4c1..961dffab9 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,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""" diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 551bcf7df..31fa17716 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/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."""