fix(logging): never lose a JSON log record to a serialization error

src/youtube_extension/backend/config/logging_config.py

@@ -62,6 +62,31 @@
 }
 
 
+# The fields ``StructuredFormatter._format_json`` builds itself, as opposed to
+# the optional enrichments a call site supplies via ``extra``. Only these are
+# retained when the full payload cannot be serialized: they are derived from
+# the LogRecord rather than from caller input, so they cannot carry the value
+# that caused the failure. See #1452.
+_JSON_CORE_FIELDS = (
+    "timestamp",
+    "service",
+    "version",
+    "level",
+    "logger",
+    "message",
+    "module",
+    "line",
+    "function",
+    "process",
+)
+
+# Last-resort record. A constant, so emitting it cannot itself fail — which is
+# what makes "a record is never lost to a serialization error" unconditional.
+_JSON_UNSERIALIZABLE_RECORD = (
+    '{"serialization_error": "log record could not be serialized"}'
+)
+
+
 def sanitize_log_record(rendered: str) -> str:
     """Neutralize line/record separators in a fully-rendered log record.
 
@@ -132,6 +157,12 @@ def _format_json(self, record: logging.LogRecord) -> str:
         the C0 controls as ``\\n``/``\\r``/``\\uXXXX``, and NEL, LS and PS as
         non-ASCII ``\\uXXXX``. The record therefore stays a single physical
         line, which is the same guarantee the line-oriented path provides.
+
+        A record is never lost to a serialization error. If the full payload
+        cannot be serialized, it degrades to ``_JSON_CORE_FIELDS`` plus a
+        ``serialization_error`` field naming the cause, and finally to a
+        constant record. The guarantee is unconditional, not limited to the
+        failure modes anticipated here (see #1452).
         """
         payload: dict[str, Any] = {
             "timestamp": self.formatTime(record, self.datefmt),
@@ -156,10 +187,35 @@ 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: a circular container is rejected
+        # structurally *before* `default` is consulted, and a value whose
+        # `__str__` raises propagates out of `default` itself. Either one would
+        # be swallowed by `Handler.handleError` and cost us the whole record, so
+        # degrade in tiers instead, and report the loss rather than hide it.
+        try:
+            return json.dumps(payload, ensure_ascii=True, default=str)
+        except Exception as exc:  # noqa: BLE001 - never lose a record
+            try:
+                detail = f"{type(exc).__name__}: {exc}"
+            except Exception:  # noqa: BLE001 - the exception's own __str__ raised
+                detail = type(exc).__name__
+
+            # Tier 2: the fields this formatter builds itself. Filtering the
+            # payload by scalar type is NOT enough — an `int` is a scalar and
+            # still fails above CPython's 4300-digit int/str conversion limit,
+            # so a large `correlation_id` would reproduce the same failure here
+            # and lose the record anyway. The optional enrichments are the only
+            # caller-supplied values in the payload, so drop them outright.
+            safe = {name: payload[name] for name in _JSON_CORE_FIELDS if name in payload}
+            safe["serialization_error"] = detail
+            try:
+                return json.dumps(safe, ensure_ascii=True)
+            except Exception:  # noqa: BLE001 - a core field was also poisoned
+                # Tier 3: a constant. It cannot fail to serialize, so the
+                # "never lost" guarantee holds unconditionally rather than
+                # only for the failures anticipated above.
+                return _JSON_UNSERIALIZABLE_RECORD
 
     def formatException(self, ei) -> str:
         """Format exception with enhanced stack trace"""

tests/unit/test_logging_config_crlf.py

@@ -20,6 +20,8 @@
 sys.path.insert(0, str(Path(__file__).resolve().parents[2] / "src"))
 
 from youtube_extension.backend.config.logging_config import (  # noqa: E402
+    _JSON_CORE_FIELDS,
+    _JSON_UNSERIALIZABLE_RECORD,
     _UNSAFE_LOG_CHARS,
     StructuredFormatter,
     sanitize_log_record,
@@ -340,3 +342,152 @@ 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)
+
+
+# ---------------------------------------------------------------------------
+# #1452: `default=str` does not deliver the guarantee its comment states.
+#
+# `default` is consulted only for values `json` cannot natively encode, and it
+# is called unguarded. Two inputs therefore still lose the record entirely --
+# the exact outcome the comment said was prevented. Both arrive through the
+# optional-enrichment loop, which is what made them reachable at all.
+# ---------------------------------------------------------------------------
+
+
+class _ExplodingStr:
+    """An `extra` value whose `__str__` raises.
+
+    `default=str` *is* consulted here, and the exception propagates straight
+    out of it -- so a narrow `except (TypeError, ValueError, RecursionError)`
+    would not catch this. That is why the guard is `except Exception`.
+    """
+
+    def __str__(self) -> str:
+        raise RuntimeError("str() exploded")
+
+
+def _circular_container() -> dict:
+    """`json.dumps` rejects this structurally, *before* reaching `default`."""
+    circular: dict = {}
+    circular["self"] = circular
+    return circular
+
+
+@pytest.mark.parametrize(
+    ("label", "poison"),
+    [
+        ("circular", _circular_container()),
+        ("exploding-str", _ExplodingStr()),
+    ],
+)
+def test_unserializable_enrichment_does_not_lose_the_record(label, poison):
+    logger, buf = _make_json_logger(f"json-serialization-{label}")
+    logger.info("payload survives", extra={"request_id": poison})
+
+    # The record must reach the sink at all -- pre-fix, `logging` swallowed the
+    # raise via Handler.handleError and dropped it.
+    rendered = buf.getvalue()
+    assert rendered.strip(), "record was lost to a serialization error"
+
+    parsed = json.loads(rendered)
+    # The fields a downstream consumer routes or alerts on stay authoritative.
+    assert parsed["level"] == "INFO"
+    assert parsed["logger"] == f"json-serialization-{label}"
+    assert parsed["message"] == "payload survives"
+    # And the loss is reported rather than hidden.
+    assert "serialization_error" in parsed
+
+
+def test_serialization_failure_is_contained_to_its_own_record():
+    # The measured pre-fix symptom was "2 of 3 records reaching the sink".
+    # Neighbouring records must be unaffected in both directions.
+    logger, buf = _make_json_logger("json-serialization-neighbours")
+    logger.info("before")
+    logger.info("poisoned", extra={"request_id": _ExplodingStr()})
+    logger.info("after")
+
+    messages = [json.loads(line)["message"] for line in buf.getvalue().splitlines()]
+    assert messages == ["before", "poisoned", "after"]
+
+
+def test_serialization_fallback_still_emits_one_physical_line():
+    # The fallback path must keep the separator guarantee the main path has,
+    # or a poisoned record could split a log line downstream.
+    logger, buf = _make_json_logger("json-serialization-oneline")
+    logger.info("a\nb\r\nc", extra={"request_id": _ExplodingStr()})
+
+    rendered = buf.getvalue()
+    assert len(rendered.splitlines()) == 1
+    assert rendered.isascii()
+    assert json.loads(rendered)["message"] == "a\nb\r\nc"
+
+
+def test_benign_json_record_has_no_serialization_error_field():
+    # The guard must be inert on the normal path -- no field, no behaviour
+    # change, for every record that serializes cleanly.
+    logger, buf = _make_json_logger("json-serialization-benign")
+    logger.info("nothing wrong here", extra={"request_id": "req-42"})
+
+    parsed = json.loads(buf.getvalue())
+    assert "serialization_error" not in parsed
+    assert parsed["correlation_id"] == "req-42"
+
+
+def test_oversized_int_enrichment_does_not_lose_the_record():
+    # A scalar-type filter is not enough. `int` is a scalar, but CPython caps
+    # int->str conversion at 4300 digits, so a large `correlation_id` fails the
+    # *fallback* serialization too and the record is lost anyway. The fallback
+    # therefore keeps only the fields the formatter builds itself.
+    logger, buf = _make_json_logger("json-serialization-bigint")
+    logger.info("payload survives", extra={"request_id": 10**4400})
+
+    rendered = buf.getvalue()
+    assert rendered.strip(), "record was lost to the int/str conversion limit"
+
+    parsed = json.loads(rendered)
+    assert parsed["level"] == "INFO"
+    assert parsed["message"] == "payload survives"
+    assert "serialization_error" in parsed
+    # The value that caused the failure must not be carried into the fallback.
+    assert "correlation_id" not in parsed
+
+
+def test_fallback_drops_only_caller_supplied_enrichments():
+    # The core fields are what make a degraded record still useful for routing
+    # and triage, so pin that they all survive rather than just `level`.
+    logger, buf = _make_json_logger("json-serialization-core-fields")
+    logger.info("still triageable", extra={"request_id": _ExplodingStr()})
+
+    parsed = json.loads(buf.getvalue())
+    for field in _JSON_CORE_FIELDS:
+        assert field in parsed, f"core field {field!r} missing from fallback"
+    assert "correlation_id" not in parsed
+
+
+def test_last_resort_record_cannot_itself_fail_to_serialize():
+    # Tier 3 is what makes the guarantee unconditional rather than "covers the
+    # failures we thought of", so assert it is valid JSON and self-describing.
+    parsed = json.loads(_JSON_UNSERIALIZABLE_RECORD)
+    assert parsed["serialization_error"]
+
+
+def test_last_resort_tier_is_reached_when_a_core_field_is_poisoned():
+    # Parsing the constant alone would still pass if the tier-3 `except` were
+    # deleted, so drive the real control path: poison a *core* field, which
+    # tier 2 retains by design, and assert the sink gets the constant record.
+    logger, buf = _make_json_logger("json-serialization-last-resort")
+
+    class _PoisonCoreField(logging.Filter):
+        def filter(self, record: logging.LogRecord) -> bool:
+            # `process` is in _JSON_CORE_FIELDS, so tier 2 cannot drop it.
+            record.process = 10**4400
+            return True
+
+    logger.addFilter(_PoisonCoreField())
+    logger.info("tier 3")
+
+    rendered = buf.getvalue()
+    assert rendered.strip(), "record was lost when both tiers failed"
+    assert rendered.strip() == _JSON_UNSERIALIZABLE_RECORD
+    assert len(rendered.splitlines()) == 1
+    assert json.loads(rendered)["serialization_error"]