From a826ecf5adc9611f85b99b2417ddc54fb7b90f47 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:13:02 +0000 Subject: [PATCH] fix(logging): close three ways the JSON fallback still lost the record MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #1491 wrapped the `json.dumps` call so a bad enrichment could not cost the whole record, and stated the guarantee as "never lose a record to a serialization error". The wrapper holds for the two inputs it was written against, but the *recovery* path it added can itself raise — so the guarantee covered the anticipated failures rather than the property. Measured against a real handler on 8517bf8, healthy -> poisoned -> healthy: | input | before | after | |------------------------------------|--------|-------| | circular container | 3/3 | 3/3 | | exploding `__str__` | 3/3 | 3/3 | | exception whose own `__str__` raises | 2/3 | 3/3 | | value forging `__class__ = str` | 2/3 | 3/3 | | int past the 4300-digit cap | 2/3 | 3/3 | | non-finite float | 3/3* | 3/3 | * emitted, but as a bare `NaN`/`Infinity` literal, which is not valid JSON — a strict downstream parser rejects the record, which is the same loss moved to the consumer. Each cause, and the fix: * The fallback built `f"{type(exc).__name__}: {exc}"` directly. The exception it catches may be one raised from a call site's own `__str__`, so describing the failure became the failure. Now `_describe_exception`, which falls back to the type name. * The scalar filter used `isinstance`, which consults `__class__` and can be forged with a property returning `str`. `json` dispatches on the real runtime type, so such a value passed the filter and then raised in the fallback's own dump. Now matched on exact runtime type. * `int` is a scalar by every type test, but `json` renders ints via `str` and CPython caps that at `sys.get_int_max_str_digits()` (4300). Now bounded by `bit_length`, which avoids performing the conversion being guarded against. * `allow_nan=False`, so a non-finite float routes to the fallback and the record stays valid JSON instead of carrying a JavaScript literal. A final constant-record tier keeps the guarantee a property of the code rather than of the failure modes anticipated here — the exact gap #1452 was about. It is not reachable through any input above, and the comment says so. Tests: +10 in the existing CWE-117 file. All 10 fail against 8517bf8 and pass after (7 failed / 26 passed -> 33 passed); the pre-existing 26 are unchanged, so this does not weaken what #1491 established. Full `tests/unit` is unchanged at 1637 failed / 76 errors (missing optional deps in this environment) with +10 passed, i.e. no regressions. ruff clean; mypy unchanged at its 17 pre-existing errors in this module. Refs #1452 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01DHLdfqAJcfL9LPWC7Dp9Gx --- .../backend/config/logging_config.py | 120 ++++++++++++++- tests/unit/test_logging_config_crlf.py | 141 ++++++++++++++++++ 2 files changed, 256 insertions(+), 5 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 2cb29f4c1..6a033e419 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/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""" diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 551bcf7df..12f7611bb 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/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."""