From 618a6043ef0309cffb2af2166d56e5eaeed87c4a Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:09:51 +0000 Subject: [PATCH] fix(logging): stop the serialization fallback from needing a fallback MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #1491 closed #1452 by re-serializing from the scalar fields when `json.dumps` fails, so a bad enrichment costs its own value rather than the whole record. One residual path still costs the record. The exception the fallback catches is not `json`'s own error. In the exploding-`__str__` case it is *whatever that* `__str__` *raised*, which is arbitrary caller code. `f"{type(exc).__name__}: {exc}"` calls `str(exc)` on it, so an exception that also raises on `str()` fails inside the handler for the failure — losing the record for exactly the reason the fallback exists to prevent. Measured against main @ 8517bf8: 2 of 3 records reach the sink. `_describe_exception` falls back to the class name, an attribute lookup that runs no user code. Also covers `performance_ms`. The enrichment loop reads two attributes and #1491 tested only `correlation_id`, leaving half the reachable surface untested. That test passes on main — it closes a coverage gap rather than pinning a fix, and is marked as such. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_013cGXYUfmU6yDSLZWe697eY --- .../backend/config/logging_config.py | 24 ++++++++- tests/unit/test_logging_config_crlf.py | 49 +++++++++++++++++++ 2 files changed, 72 insertions(+), 1 deletion(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 2cb29f4c1..049f1f360 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -76,6 +76,25 @@ def sanitize_log_record(rendered: str) -> str: return rendered.translate(_UNSAFE_LOG_CHARS) +def _describe_exception(exc: BaseException) -> str: + """Name an exception without trusting its ``__str__``. + + Used only by ``StructuredFormatter._format_json``'s serialization + fallback. That fallback exists because a value whose ``__str__`` raises + costs the record — but the exception it catches is then *whatever that* + ``__str__`` *raised*, which is arbitrary and may itself raise on + ``str()``. Interpolating it directly would fail inside the handler for + the failure, losing the record for the same reason one level down. + + The class name is the guaranteed-safe floor: an attribute lookup that + runs no user code. + """ + 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. @@ -172,7 +191,10 @@ def _format_json(self, record: logging.LogRecord) -> str: for key, value in payload.items() if isinstance(value, (str, int, float, bool, type(None))) } - safe["serialization_error"] = f"{type(exc).__name__}: {exc}" + # Described via `_describe_exception`, not interpolated directly: + # `exc` is whatever the offending `__str__` raised, so `str(exc)` + # can raise in turn and cost the record here instead. + safe["serialization_error"] = _describe_exception(exc) return json.dumps(safe, ensure_ascii=True, default=str) def formatException(self, ei) -> str: diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 551bcf7df..d9c826622 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -369,6 +369,55 @@ def test_exploding_str_correlation_id_does_not_cost_the_record(): assert poisoned["serialization_error"] == "RuntimeError: str() exploded" +def test_exploding_str_performance_ms_does_not_cost_the_record(): + # `correlation_id` is covered above, but the enrichment loop reads *two* + # attributes and `performance_ms` is the other one. It arrives by a + # different route — set from `record.duration` in `format()`, or straight + # from `extra=` as here — so covering only `correlation_id` leaves half + # the reachable surface untested. + logger, buf = _make_json_logger("json-exploding-perf") + logger.info("healthy one") + logger.info("poisoned", extra={"performance_ms": _ExplodingStr()}) + logger.info("after poison") + records = [json.loads(line) for line in buf.getvalue().splitlines() if line.strip()] + + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + assert poisoned["level"] == "INFO" + assert "performance_ms" not in poisoned + + +def test_fallback_survives_an_exception_whose_own_str_raises(): + """The fallback must not need a fallback. + + `exc` here is not `json`'s own error — it is whatever the offending + `__str__` raised, so it is arbitrary caller code. If that exception also + raises on `str()`, interpolating it into `serialization_error` fails + *inside the handler for the failure*, and the record is lost for exactly + the reason the fallback exists to prevent. Measured at 2 of 3 records + reaching the sink before `_describe_exception`. + """ + + class _NastyError(Exception): + def __str__(self) -> str: + raise RuntimeError("even the error explodes") + + class _RaisesNasty: + def __str__(self) -> str: + raise _NastyError() + + records = _emit_three("json-nested-explosion", _RaisesNasty()) + + assert len(records) == 3 + poisoned = records[1] + assert poisoned["message"] == "poisoned" + assert poisoned["level"] == "INFO" + assert "correlation_id" not in poisoned + # Degraded to the class name alone rather than lost entirely. + assert poisoned["serialization_error"] == "_NastyError" + + def test_serialization_fallback_still_escapes_attacker_content(): # The fallback must not become a hole in the #1429 fix: a forgery payload # in `message` has to stay escaped on the degraded path too.