diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..7a7c002e5 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -156,10 +156,47 @@ 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 values `json` cannot natively encode, but it is + # not sufficient on its own to keep a record alive (#1452): + # + # * a circular container is rejected structurally, *before* `default` + # is ever consulted, so `default=str` cannot see it; + # * a value whose ``__str__`` raises propagates that exception out of + # `default` itself. + # + # Either way `json.dumps` raises inside the logging path, `logging` + # swallows it via ``Handler.handleError``, and the record is dropped + # entirely. Only the optional enrichments can carry such a value, so the + # fallback keeps every scalar field — including `level`, which routing + # and alerting depend on — and reports what went wrong in-band. + # `exception` and `stack_info` are already rendered to `str` above, so + # they survive the fallback too. + # + # SCOPE, stated precisely because the bug this fixes was a comment + # claiming more than its code enforced: this guards the *serialization* + # boundary only. `payload` is built above it, so a raise from + # ``getMessage()`` (bad %-args), ``formatTime``, ``formatException`` or + # ``formatStack`` is still fatal to the record — those are pre-existing + # and shared with the line-oriented path, which has the same exposure. + try: + return json.dumps(payload, ensure_ascii=True, default=str) + except Exception as exc: # noqa: BLE001 - no serialization error may cost a record + safe = { + key: value + for key, value in payload.items() + if isinstance(value, (str, int, float, bool, type(None))) + } + # Rendering `exc` calls its own ``__str__``, which is exactly the + # thing that can raise here — a value whose ``__str__`` raises an + # exception that itself raises from ``__str__``. Reachable, and + # covered by a test. A fallback that can become the thing that + # loses the record is not a fallback. + try: + detail = f"{type(exc).__name__}: {exc}" + except Exception: # noqa: BLE001 - the reporter must not raise + detail = type(exc).__name__ + safe["serialization_error"] = detail + return json.dumps(safe, ensure_ascii=True, default=str) 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..edf2a8470 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -340,3 +340,153 @@ def test_setup_logging_wires_json_output_to_the_formatter( ] assert formatters, "expected StructuredFormatter on the root logger" assert all(f.json_output is enable_json for f in formatters) + + +# --------------------------------------------------------------------------- +# Record loss on the JSON path (#1452) +# +# `_format_json` passed `default=str` to `json.dumps` and claimed that kept a +# non-serializable `extra` value from costing us the record. It does not: +# +# * a circular container is rejected structurally, before `default` is ever +# consulted -- so `default=str` never sees it; +# * a value whose `__str__` raises propagates that exception out of `default`. +# +# Either way `json.dumps` raises inside the logging path, `logging` swallows it +# via `Handler.handleError`, and the record is dropped. These tests assert the +# record survives *and* that `level` stays authoritative, since a record that +# survives with the wrong level is no better for routing or alerting. +# +# Reachable only through the optional enrichments (`correlation_id`, +# `performance_ms`); every live call site passes a scalar today. +# --------------------------------------------------------------------------- + + +class _ExplodingStr: + """An `extra` value whose ``__str__`` raises -- walks through `default=str`.""" + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _circular() -> dict: + circular: dict = {} + circular["self"] = circular + return circular + + +@pytest.mark.parametrize( + ("label", "poison"), + [ + # `default` is never consulted -- json.dumps rejects the cycle first. + ("circular", _circular()), + # `default` IS consulted, and str() raises straight back out of it. + ("exploding-str", _ExplodingStr()), + ], +) +def test_unserializable_enrichment_does_not_lose_the_record(label, poison): + logger, buf = _make_json_logger(f"json-loss-{label}") + logger.info("payload survives", extra={"request_id": poison}) + + lines = [line for line in buf.getvalue().splitlines() if line.strip()] + assert len(lines) == 1, f"the record was dropped entirely ({label})" + + parsed = json.loads(lines[0]) + # The fields routing and alerting depend on must survive intact. + assert parsed["level"] == "INFO" + assert parsed["message"] == "payload survives" + assert parsed["logger"] == f"json-loss-{label}" + # ...and the failure is reported in-band rather than silently swallowed. + assert "serialization_error" in parsed + + +@pytest.mark.parametrize("poison", [_circular(), _ExplodingStr()]) +def test_neighbouring_records_are_unaffected(poison): + # The real cost of the bug was a gap in the log, so pin the sequence: a + # poisoned record must not take healthy ones down with it. + logger, buf = _make_json_logger("json-loss-sequence") + logger.info("before") + logger.info("poisoned", extra={"request_id": poison}) + logger.info("after") + + messages = [ + json.loads(line)["message"] + for line in buf.getvalue().splitlines() + if line.strip() + ] + assert messages == ["before", "poisoned", "after"] + + +def test_serialization_fallback_stays_a_single_parseable_line(): + # The fallback must not regain the properties the main path guarantees: + # one physical line, pure ASCII, and no forged field from the message. + logger, buf = _make_json_logger("json-loss-shape") + logger.warning( + 'nasty\r\n", "level": "DEBUG', extra={"request_id": _ExplodingStr()} + ) + out = buf.getvalue() + + assert out.count("\n") == 1 # only the handler's terminator + assert out.isascii() + parsed = json.loads(out) + assert parsed["level"] == "WARNING" # not the forged DEBUG + assert parsed["message"] == 'nasty\r\n", "level": "DEBUG' + + +def test_serializable_enrichments_still_reach_the_json_record(): + # Guard the fallback's blast radius: it drops non-scalar fields, so prove + # the normal path is untouched and scalar enrichments still appear. + logger, buf = _make_json_logger("json-loss-happy") + 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 _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 the inner guard in `_format_json` live code rather than + defensive decoration: building `f"{type(exc).__name__}: {exc}"` calls the + raised exception's `__str__`, which raises again. + """ + + def __str__(self) -> str: + raise _ExplodingError() + + +def test_exception_whose_str_also_raises_does_not_lose_the_record(): + logger, buf = _make_json_logger("json-loss-nested") + 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 cost us the traceback. Asserted because I claimed the + # opposite in review and was wrong. + logger, buf = _make_json_logger("json-loss-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