fix(logging): stop a bad enrichment value losing the whole JSON record

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"""

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