diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..59f1593c8 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,48 @@ 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 filter for the serialization fallback (#1452). The fallback's own dump + has no ``default=``, deliberately — 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 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 + ``default``-less dump, raises ``TypeError``, and costs the record the + fallback exists to save. ``json`` itself dispatches on the real runtime + type, which cannot be forged, so matching on it is what makes this filter + agree with the encoder. Credit to #1471 for catching this. + + Non-finite floats are excluded: ``json`` renders them as the JavaScript + literals ``NaN``/``Infinity``, which are not valid JSON, so a strict + downstream parser would reject the whole record. + """ + value_type = type(value) + if value_type is float: + return math.isfinite(value) + return value_type 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 whole point + is that a record survives. ``str(exc)`` is itself attacker-adjacent there: + the exception can come from a call site's own ``__str__``, so it may be an + instance of a class whose ``__str__`` raises too. The type name is a plain + attribute lookup and is always safe. + """ + 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. @@ -156,10 +199,52 @@ def _format_json(self, record: logging.LogRecord) -> str: if hasattr(record, attribute): payload[attribute] = getattr(record, attribute) - # `default=str` keeps a non-serializable `extra` value from raising - # inside the logging path, where an exception would be swallowed and - # the record lost entirely. - return json.dumps(payload, ensure_ascii=True, default=str) + # `default=str` handles the common case — an `extra` value of a type + # `json` cannot natively encode — but it is NOT sufficient on its own, + # and the fallback below is what makes a payload always serializable + # (#1452). Three inputs defeat `default=str`: + # + # * a circular container, which ``json.dumps`` rejects structurally + # *before* ``default`` is ever consulted; + # * a value whose ``__str__`` raises, where ``default`` is consulted + # and the exception propagates straight back out of it; + # * a non-finite float, which ``default`` is never consulted for + # either — see ``allow_nan=False`` below. + # + # Each raises inside ``Handler.emit``, where ``logging`` swallows it via + # ``handleError`` and drops the record entirely. Only the optional + # enrichments can carry such a value, so the fallback keeps every + # JSON-safe scalar — including `level`, which downstream consumers route + # and alert on — and reports what was dropped. + # + # 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 (``super().format()`` calls + # ``getMessage()`` too). This is not a "no record is ever lost" + # guarantee; it is a "serialization never loses one". + # + # ``allow_nan=False`` because Python's default emits the JavaScript + # literals ``NaN``/``Infinity``, which are not valid JSON. A strict + # downstream parser rejects the record — the same loss as dropping it + # here, just moved to the consumer where it is harder to see. Raising + # instead routes it to the fallback, which drops the offending + # enrichment and keeps a record every parser accepts. + try: + return json.dumps( + payload, ensure_ascii=True, allow_nan=False, default=str + ) + except Exception as exc: # noqa: BLE001 - a record is never worth losing + safe: dict[str, Any] = { + key: value + for key, value in payload.items() + if _is_json_safe_scalar(value) + } + safe["serialization_error"] = _describe_exception(exc) + # Cannot raise: `_is_json_safe_scalar` admits only values the + # encoder emits directly, and `allow_nan=False` has nothing left to + # reject because non-finite floats were filtered out above. + 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 509038ae6..84eabf9cb 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -22,6 +22,7 @@ from youtube_extension.backend.config.logging_config import ( # noqa: E402 _UNSAFE_LOG_CHARS, StructuredFormatter, + _describe_exception, sanitize_log_record, setup_logging, ) @@ -309,6 +310,211 @@ def test_line_oriented_path_is_untouched_by_the_json_fix(): assert buf.getvalue() == "INFO - all good video-123\n" +# --- #1452: a record must survive an unserializable enrichment ------------- +# +# `default=str` alone does not deliver "never lose a record". Both payloads +# below raise out of `json.dumps`, inside `Handler.emit`, where `logging` +# swallows the exception via `handleError` and drops the record silently. +# `correlation_id` is the reachable field: it is populated from +# `record.request_id`, which middleware may set to a framework object. + + +class _ExplodingStr: + """A value whose ``__str__`` raises — `default=str` propagates it.""" + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _circular_container() -> dict: + """`json.dumps` rejects this structurally, before `default` is consulted.""" + circular: dict = {} + circular["self"] = circular + return circular + + +@pytest.mark.parametrize( + ("label", "poison"), + [ + ("circular", _circular_container()), + ("exploding-str", _ExplodingStr()), + ], +) +def test_unserializable_enrichment_does_not_cost_the_record(label, poison): + logger, buf = _make_json_logger(f"json-unserializable-{label}") + logger.info("healthy before") + logger.info("poisoned record", extra={"request_id": poison}) + logger.info("healthy after") + + lines = [line for line in buf.getvalue().splitlines() if line.strip()] + # The pre-#1452 implementation emits 2 — the poisoned record is dropped. + assert len(lines) == 3 + + parsed = json.loads(lines[1]) + # `level` stays authoritative, which is what downstream routing alerts on. + assert parsed["level"] == "INFO" + assert parsed["message"] == "poisoned record" + # The unserializable enrichment is dropped, and says so rather than + # vanishing silently. + assert "correlation_id" not in parsed + assert "serialization_error" in parsed + + +def test_serialization_fallback_keeps_the_record_a_single_json_line(): + # The fallback must honour the same two guarantees as the happy path: + # one physical line, and no forged field from attacker content. + logger, buf = _make_json_logger("json-unserializable-forgery") + logger.info(_FORGERY, extra={"request_id": _ExplodingStr()}) + + rendered = buf.getvalue() + assert rendered.count("\n") == 1 + parsed = json.loads(rendered) + + assert parsed["level"] == "INFO" + assert "forged" not in parsed + assert parsed["message"] == _FORGERY + + +def test_benign_enrichments_still_reach_the_json_record(): + # The fallback must not fire on serializable values — a scalar + # `correlation_id` still rides through the normal path. + logger, buf = _make_json_logger("json-benign-enrichment") + logger.info("fine", extra={"request_id": "req-123"}) + parsed = json.loads(buf.getvalue()) + + assert parsed["correlation_id"] == "req-123" + assert "serialization_error" not in parsed + + +class _ForgedClassStr: + """A value that lies about its type *and* raises from `__str__`. + + `isinstance(x, str)` consults `x.__class__`, which this forges. It + therefore passes an `isinstance`-based scalar filter, reaches the + fallback's `default`-less `json.dumps`, and raises `TypeError` — losing the + record the fallback exists to save. `json` dispatches on the real runtime + type, so `type(value) is` agrees with the encoder and `isinstance` does not. + """ + + @property + def __class__(self): # type: ignore[override] + return str + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +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 dropped. + logger, buf = _make_json_logger("json-forged-class") + logger.info("before") + logger.info("survives a liar", extra={"request_id": _ForgedClassStr()}) + logger.info("after") + + messages = [ + json.loads(line)["message"] + for line in buf.getvalue().splitlines() + if line.strip() + ] + assert messages == ["before", "survives a liar", "after"] + + parsed = json.loads(buf.getvalue().splitlines()[1]) + assert parsed["level"] == "INFO" + assert "correlation_id" not in parsed + assert parsed["serialization_error"].startswith("RuntimeError") + + +@pytest.mark.parametrize("value", [float("inf"), float("-inf"), float("nan")]) +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}) + + rendered = buf.getvalue() + + def _reject(constant: str) -> None: + raise AssertionError(f"non-JSON constant in record: {constant}") + + parsed = json.loads(rendered, 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={"request_id": 12.5}) + parsed = json.loads(buf.getvalue()) + + assert parsed["correlation_id"] == 12.5 + assert "serialization_error" not in parsed + + +class _ExplodingError(Exception): + """An exception whose own `__str__` raises.""" + + def __str__(self) -> str: + raise RuntimeError("the error's own __str__ exploded") + + +class _NestedExplodingStr: + """`__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 _ExplodingError() + + +def test_exception_whose_str_also_raises_does_not_lose_the_record(): + # Credit to #1471/#1472 for exercising this end-to-end; the helper's own + # unit test above cannot show the path is reachable through the formatter. + logger, buf = _make_json_logger("json-nested-exploding") + logger.info("still emitted", extra={"request_id": _NestedExplodingStr()}) + + lines = [line for line in buf.getvalue().splitlines() if line.strip()] + assert len(lines) == 1, "the nested-raise path dropped the record" + + parsed = json.loads(lines[0]) + assert parsed["level"] == "INFO" + assert parsed["message"] == "still emitted" + # The type name is still reportable even when rendering the value is not. + assert parsed["serialization_error"] == "_ExplodingError" + + +def test_rendered_traceback_survives_the_serialization_fallback(): + # `exception` is rendered to `str` before the guarded dump, so a failing + # enrichment must not also cost us the traceback. + logger, buf = _make_json_logger("json-fallback-traceback") + try: + raise ValueError("the real cause") + except ValueError: + logger.error("failed", exc_info=True, extra={"request_id": _ExplodingStr()}) + + parsed = json.loads(buf.getvalue()) + assert "serialization_error" in parsed # the fallback did fire + assert "the real cause" in parsed["exception"] # ...and kept the traceback + + +def test_describe_exception_survives_an_exception_that_cannot_be_stringified(): + # The fallback formats the error it caught. If that exception's own + # __str__ raises, describing it must not re-raise and re-lose the record. + class _Unprintable(Exception): + def __str__(self) -> str: + raise RuntimeError("nested boom") + + assert _describe_exception(_Unprintable()) == "_Unprintable" + + @pytest.fixture def _restore_root_logging(): """`setup_logging` calls dictConfig, which mutates global logging state."""