diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..969360be8 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/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""" diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 509038ae6..31464ae41 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/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"]