From 90a013acf0fab8765b14f9d6140cfc1a1accc146 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 20:54:19 +0000 Subject: [PATCH 1/4] fix(logging): keep the record when a JSON enrichment cannot serialize MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes #1452. `_format_json` (added in #1439) claimed `default=str` meant "a record is never lost to a serialization error". It does not. `default` is consulted only for values json cannot natively encode, and it is called unguarded, so two inputs still raise out of json.dumps inside Handler.emit — where logging swallows the exception via handleError and drops the record: * a circular container, rejected structurally before `default` runs; * a value whose __str__ raises, propagating back out of `default`. Reproduced on main, three logger.info calls with the middle one poisoned: 2 of 3 records reached the sink, for both inputs. Wraps the dump in a fallback that keeps every JSON-native scalar — so `level`, which downstream routing and alerting key on, stays authoritative — drops the unserializable enrichment, and records what failed in a `serialization_error` field rather than letting it vanish. `except Exception` deliberately, not a narrow tuple: (TypeError, ValueError, RecursionError) looks more correct but the exploding-__str__ case walks straight through it. Adds `_describe_exception`, because formatting the caught exception is itself the same hazard — it can come from a call site's own __str__, so its class may be one whose __str__ raises too. Falls back to the type name, a plain attribute lookup. Reachable via extra={"request_id": ...}, which populates `correlation_id` and which middleware may set to a framework object. Not a vulnerability and not reachable from request content: an attacker-supplied header is a string, and strings were already escaped correctly. The CWE-117 field forgery fix from #1429/#1439 is untouched. Verification on this head: * tests/unit/test_logging_config_crlf.py — 25 passed, the 20 from main unchanged, so the line-oriented and forgery contracts still hold. * Non-vacuous, and precisely: removing only the fallback block fails exactly the 3 tests that cover it (3 failed, 22 passed). * Reproduction now emits 3 of 3 records for both inputs, level=INFO, with serialization_error naming the cause. * Benign scalar enrichments still take the normal path — the fallback does not fire, and correlation_id still lands in the record. * ruff clean on both changed files. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_0146p7ZfxtbdEfJjtgETZTNf --- .../backend/config/logging_config.py | 45 +++++++++- tests/unit/test_logging_config_crlf.py | 87 +++++++++++++++++++ 2 files changed, 128 insertions(+), 4 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index c0fd5fcaf..d54fcecdf 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -76,6 +76,21 @@ def sanitize_log_record(rendered: str) -> str: return rendered.translate(_UNSAFE_LOG_CHARS) +def _describe_exception(exc: BaseException) -> str: + """Describe an exception without ever raising a second one. + + Used on the JSON serialization fallback path (#1452), where the whole point + is that a record survives. ``str(exc)`` is itself attacker-adjacent there: + the exception can come from a call site's own ``__str__``, so it may be an + instance of a class whose ``__str__`` raises too. The type name is a plain + attribute lookup and is always safe. + """ + try: + return f"{type(exc).__name__}: {exc}" + except Exception: # noqa: BLE001 - the type name alone still identifies it + return type(exc).__name__ + + class StructuredFormatter(logging.Formatter): """ Custom formatter for structured logging with enhanced metadata. @@ -156,10 +171,32 @@ 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 the common case — an `extra` value of a type + # `json` cannot natively encode — but it is NOT sufficient on its own, + # and the fallback below is what actually delivers "never lose a + # record" (#1452). Two inputs defeat it: + # + # * a circular container, which ``json.dumps`` rejects structurally + # *before* ``default`` is ever consulted; + # * a value whose ``__str__`` raises, where ``default`` is consulted + # and the exception propagates straight back out of it. + # + # Either one raises inside ``Handler.emit``, where ``logging`` swallows + # it via ``handleError`` and drops the record entirely. Only the + # optional enrichments can carry such a value, so the fallback keeps + # every scalar field — including `level`, which downstream consumers + # route and alert on — and reports what was dropped. + try: + return json.dumps(payload, ensure_ascii=True, default=str) + except Exception as exc: # noqa: BLE001 - a record is never worth losing + safe: dict[str, Any] = { + key: value + for key, value in payload.items() + if isinstance(value, (str, int, float, bool, type(None))) + } + safe["serialization_error"] = _describe_exception(exc) + # Cannot raise: every remaining value is a JSON-native scalar. + return json.dumps(safe, ensure_ascii=True) 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..d4d1520e5 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -22,6 +22,7 @@ from youtube_extension.backend.config.logging_config import ( # noqa: E402 _UNSAFE_LOG_CHARS, StructuredFormatter, + _describe_exception, sanitize_log_record, setup_logging, ) @@ -309,6 +310,92 @@ def test_line_oriented_path_is_untouched_by_the_json_fix(): assert buf.getvalue() == "INFO - all good video-123\n" +# --- #1452: a record must survive an unserializable enrichment ------------- +# +# `default=str` alone does not deliver "never lose a record". Both payloads +# below raise out of `json.dumps`, inside `Handler.emit`, where `logging` +# swallows the exception via `handleError` and drops the record silently. +# `correlation_id` is the reachable field: it is populated from +# `record.request_id`, which middleware may set to a framework object. + + +class _ExplodingStr: + """A value whose ``__str__`` raises — `default=str` propagates it.""" + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def _circular_container() -> dict: + """`json.dumps` rejects this structurally, before `default` is consulted.""" + circular: dict = {} + circular["self"] = circular + return circular + + +@pytest.mark.parametrize( + ("label", "poison"), + [ + ("circular", _circular_container()), + ("exploding-str", _ExplodingStr()), + ], +) +def test_unserializable_enrichment_does_not_cost_the_record(label, poison): + logger, buf = _make_json_logger(f"json-unserializable-{label}") + logger.info("healthy before") + logger.info("poisoned record", extra={"request_id": poison}) + logger.info("healthy after") + + lines = [line for line in buf.getvalue().splitlines() if line.strip()] + # The pre-#1452 implementation emits 2 — the poisoned record is dropped. + assert len(lines) == 3 + + parsed = json.loads(lines[1]) + # `level` stays authoritative, which is what downstream routing alerts on. + assert parsed["level"] == "INFO" + assert parsed["message"] == "poisoned record" + # The unserializable enrichment is dropped, and says so rather than + # vanishing silently. + assert "correlation_id" not in parsed + assert "serialization_error" in parsed + + +def test_serialization_fallback_keeps_the_record_a_single_json_line(): + # The fallback must honour the same two guarantees as the happy path: + # one physical line, and no forged field from attacker content. + logger, buf = _make_json_logger("json-unserializable-forgery") + logger.info(_FORGERY, extra={"request_id": _ExplodingStr()}) + + rendered = buf.getvalue() + assert rendered.count("\n") == 1 + parsed = json.loads(rendered) + + assert parsed["level"] == "INFO" + assert "forged" not in parsed + assert parsed["message"] == _FORGERY + + +def test_benign_enrichments_still_reach_the_json_record(): + # The fallback must not fire on serializable values — a scalar + # `correlation_id` still rides through the normal path. + logger, buf = _make_json_logger("json-benign-enrichment") + 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 + + +def test_describe_exception_survives_an_exception_that_cannot_be_stringified(): + # The fallback formats the error it caught. If that exception's own + # __str__ raises, describing it must not re-raise and re-lose the record. + class _Unprintable(Exception): + def __str__(self) -> str: + raise RuntimeError("nested boom") + + assert _describe_exception(_Unprintable()) == "_Unprintable" + + @pytest.fixture def _restore_root_logging(): """`setup_logging` calls dictConfig, which mutates global logging state.""" From 7af1ae56be9b184fe0f65a272552614ff42c7c3e Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 20:58:37 +0000 Subject: [PATCH 2/4] fix(logging): reject non-finite floats so JSON records stay strictly valid MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Found by the runbook's red-team pass over this PR's own diff, probing the claim that the fallback makes the payload always serializable. A third input defeats `default=str`, and it is quieter than the other two: `json.dumps` renders a non-finite float as the JavaScript literals `NaN` /`Infinity`, which are not valid JSON. It does not raise, so the record is emitted and looks fine — then a strict downstream parser rejects it. That is the same loss the rest of this PR prevents, relocated to the consumer where it is harder to see. `json.loads` accepts those literals by default, which is why the existing tests could not catch it. Reachable the same way as the other two, via extra={"request_id": ...} -> correlation_id; a duration-derived metric is a plausible source of inf. `allow_nan=False` on both dumps turns it into a raise, which routes to the fallback. `_is_json_safe_scalar` replaces the inline isinstance filter so the fallback drops non-finite floats too rather than re-emitting them -- otherwise the guard would just move the invalid literal one line down. Also narrows the scope note: this is a "serialization never loses a record" guarantee, not "no record is ever lost". Building the payload can still raise upstream of the try -- record.getMessage() on mismatched %-args is the reachable case -- and that is out of scope because it fails the line-oriented path identically via super().format(). The previous comment claimed the broader guarantee, which is the exact defect class #1452 exists to close. Verification on this head: * tests/unit/test_logging_config_crlf.py -- 29 passed. * Non-vacuous: removing only allow_nan=False fails exactly the 3 non-finite tests (3 failed, 26 passed). The finite-float test keeps passing, so the guard is not just rejecting all floats. * 10-probe red-team sweep: circular, exploding __str__, inf, nan, deep nesting (RecursionError), exc_info whose __str__ raises, lone surrogate, forgery payload + poisoned enrichment, benign scalar -- all emit one physical line of strictly-valid JSON with level authoritative. Bad %-args still loses the record, as documented. * ruff clean on both changed files. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_0146p7ZfxtbdEfJjtgETZTNf --- .../backend/config/logging_config.py | 58 +++++++++++++++---- tests/unit/test_logging_config_crlf.py | 31 ++++++++++ 2 files changed, 77 insertions(+), 12 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index d54fcecdf..6cff4c99c 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -10,6 +10,7 @@ import json import logging import logging.config +import math import os import sys from datetime import datetime @@ -76,6 +77,19 @@ def sanitize_log_record(rendered: str) -> str: return rendered.translate(_UNSAFE_LOG_CHARS) +def _is_json_safe_scalar(value: object) -> bool: + """Is this a value ``json.dumps`` emits directly, under ``allow_nan=False``? + + The filter for the serialization fallback (#1452). Deliberately excludes + non-finite floats: ``json`` renders them as the JavaScript literals + ``NaN``/``Infinity``, which are not valid JSON, so a strict downstream + parser would reject the whole record. + """ + if isinstance(value, float): + return math.isfinite(value) + return isinstance(value, (str, bool, int, type(None))) + + def _describe_exception(exc: BaseException) -> str: """Describe an exception without ever raising a second one. @@ -173,30 +187,50 @@ def _format_json(self, record: logging.LogRecord) -> str: # `default=str` handles the common case — an `extra` value of a type # `json` cannot natively encode — but it is NOT sufficient on its own, - # and the fallback below is what actually delivers "never lose a - # record" (#1452). Two inputs defeat it: + # and the fallback below is what makes a payload always serializable + # (#1452). Three inputs defeat `default=str`: # # * a circular container, which ``json.dumps`` rejects structurally # *before* ``default`` is ever consulted; # * a value whose ``__str__`` raises, where ``default`` is consulted - # and the exception propagates straight back out of it. + # and the exception propagates straight back out of it; + # * a non-finite float, which ``default`` is never consulted for + # either — see ``allow_nan=False`` below. + # + # Each raises inside ``Handler.emit``, where ``logging`` swallows it via + # ``handleError`` and drops the record entirely. Only the optional + # enrichments can carry such a value, so the fallback keeps every + # JSON-safe scalar — including `level`, which downstream consumers route + # and alert on — and reports what was dropped. + # + # SCOPE: this covers *serializing* the payload. Building it can still + # raise upstream of here — ``record.getMessage()`` on mismatched + # ``%``-args is the reachable case — and that is out of scope because it + # fails the line-oriented path identically (``super().format()`` calls + # ``getMessage()`` too). This is not a "no record is ever lost" + # guarantee; it is a "serialization never loses one". # - # Either one raises inside ``Handler.emit``, where ``logging`` swallows - # it via ``handleError`` and drops the record entirely. Only the - # optional enrichments can carry such a value, so the fallback keeps - # every scalar field — including `level`, which downstream consumers - # route and alert on — and reports what was dropped. + # ``allow_nan=False`` because Python's default emits the JavaScript + # literals ``NaN``/``Infinity``, which are not valid JSON. A strict + # downstream parser rejects the record — the same loss as dropping it + # here, just moved to the consumer where it is harder to see. Raising + # instead routes it to the fallback, which drops the offending + # enrichment and keeps a record every parser accepts. try: - return json.dumps(payload, ensure_ascii=True, default=str) + return json.dumps( + payload, ensure_ascii=True, allow_nan=False, default=str + ) except Exception as exc: # noqa: BLE001 - a record is never worth losing safe: dict[str, Any] = { key: value for key, value in payload.items() - if isinstance(value, (str, int, float, bool, type(None))) + if _is_json_safe_scalar(value) } safe["serialization_error"] = _describe_exception(exc) - # Cannot raise: every remaining value is a JSON-native scalar. - return json.dumps(safe, ensure_ascii=True) + # Cannot raise: `_is_json_safe_scalar` admits only values the + # encoder emits directly, and `allow_nan=False` has nothing left to + # reject because non-finite floats were filtered out above. + return json.dumps(safe, ensure_ascii=True, allow_nan=False) 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 d4d1520e5..8fefd8174 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -386,6 +386,37 @@ def test_benign_enrichments_still_reach_the_json_record(): assert "serialization_error" not in parsed +@pytest.mark.parametrize("value", [float("inf"), float("-inf"), float("nan")]) +def test_non_finite_enrichment_does_not_produce_invalid_json(value): + # Python's json emits the JavaScript literals NaN/Infinity for these, which + # are not valid JSON — a strict downstream parser rejects the whole record, + # which is the same loss as dropping it, moved to the consumer. `json.loads` + # accepts them by default, so this asserts against a *strict* parse. + logger, buf = _make_json_logger(f"json-non-finite-{value}") + logger.info("measured", extra={"request_id": value}) + + rendered = buf.getvalue() + + def _reject(constant: str) -> None: + raise AssertionError(f"non-JSON constant in record: {constant}") + + parsed = json.loads(rendered, parse_constant=_reject) + assert parsed["level"] == "INFO" + assert parsed["message"] == "measured" + assert "correlation_id" not in parsed + assert "serialization_error" in parsed + + +def test_finite_float_enrichment_is_kept(): + # The non-finite guard must not cost ordinary numeric enrichments. + logger, buf = _make_json_logger("json-finite-float") + logger.info("measured", extra={"request_id": 12.5}) + parsed = json.loads(buf.getvalue()) + + assert parsed["correlation_id"] == 12.5 + assert "serialization_error" not in parsed + + def test_describe_exception_survives_an_exception_that_cannot_be_stringified(): # The fallback formats the error it caught. If that exception's own # __str__ raises, describing it must not re-raise and re-lose the record. From 5af0db8e93234a84535d7d9110bb3d0ab16f8730 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:01:18 +0000 Subject: [PATCH 3/4] fix(logging): match the encoder's real type in the fallback filter Credit to #1471, a competing implementation of #1452 opened two minutes before this one, which caught a hole in this branch's filter. The fallback's json.dumps has no `default=` on purpose -- anything reaching `default` there would reinstate the raising-__str__ hole -- so the scalar filter is the only thing preventing a second, fatal raise. Written with `isinstance`, it does not hold: `isinstance` consults `value.__class__`, which an object can forge with a property returning `str`. Such a value passes the filter, reaches the default-less dump, raises TypeError, and costs the record the fallback exists to save. Reproduced against this branch's previous head: isinstance(v, str) : True _is_json_safe_scalar(v) : True <- passes fallback json.dumps : TypeError end-to-end : 2 of 3 records reached the sink `json` dispatches on the real runtime type, which cannot be forged, so `type(value) is` is what makes this filter agree with the encoder rather than merely assert agreement. Note the two findings are independent and both are needed: #1471's filter is exact about the type but still admits non-finite floats, which serialize without raising into the invalid JSON literals NaN/Infinity. This keeps the finite check on top of the exact-type match. Verification: * 30 passed. * Non-vacuous: restoring the isinstance form fails exactly the new forged-class test (1 failed, 29 passed). * ruff clean. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_0146p7ZfxtbdEfJjtgETZTNf --- .../backend/config/logging_config.py | 26 ++++++++++--- tests/unit/test_logging_config_crlf.py | 39 +++++++++++++++++++ 2 files changed, 59 insertions(+), 6 deletions(-) diff --git a/src/youtube_extension/backend/config/logging_config.py b/src/youtube_extension/backend/config/logging_config.py index 6cff4c99c..59f1593c8 100644 --- a/src/youtube_extension/backend/config/logging_config.py +++ b/src/youtube_extension/backend/config/logging_config.py @@ -80,14 +80,28 @@ def sanitize_log_record(rendered: str) -> str: def _is_json_safe_scalar(value: object) -> bool: """Is this a value ``json.dumps`` emits directly, under ``allow_nan=False``? - The filter for the serialization fallback (#1452). Deliberately excludes - non-finite floats: ``json`` renders them as the JavaScript literals - ``NaN``/``Infinity``, which are not valid JSON, so a strict downstream - parser would reject the whole record. + The filter for the serialization fallback (#1452). The fallback's own dump + has no ``default=``, deliberately — anything reaching ``default`` there + would reinstate the raising-``__str__`` hole — so this filter is the only + thing standing between it and a second, fatal raise. It is exact about two + things: + + ``type(value) is``, never ``isinstance``. ``isinstance`` consults + ``value.__class__``, which an object can forge with a property returning + ``str``. Such a value passes an ``isinstance`` filter, reaches the + ``default``-less dump, raises ``TypeError``, and costs the record the + fallback exists to save. ``json`` itself dispatches on the real runtime + type, which cannot be forged, so matching on it is what makes this filter + agree with the encoder. Credit to #1471 for catching this. + + Non-finite floats are excluded: ``json`` renders them as the JavaScript + literals ``NaN``/``Infinity``, which are not valid JSON, so a strict + downstream parser would reject the whole record. """ - if isinstance(value, float): + value_type = type(value) + if value_type is float: return math.isfinite(value) - return isinstance(value, (str, bool, int, type(None))) + return value_type in (str, bool, int, type(None)) def _describe_exception(exc: BaseException) -> str: diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index 8fefd8174..ea016f067 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -386,6 +386,45 @@ def test_benign_enrichments_still_reach_the_json_record(): assert "serialization_error" not in parsed +class _ForgedClassStr: + """A value that lies about its type *and* raises from `__str__`. + + `isinstance(x, str)` consults `x.__class__`, which this forges. It + therefore passes an `isinstance`-based scalar filter, reaches the + fallback's `default`-less `json.dumps`, and raises `TypeError` — losing the + record the fallback exists to save. `json` dispatches on the real runtime + type, so `type(value) is` agrees with the encoder and `isinstance` does not. + """ + + @property + def __class__(self): # type: ignore[override] + return str + + def __str__(self) -> str: + raise RuntimeError("str() exploded") + + +def test_fallback_filter_is_not_fooled_by_a_forged_class(): + # Pins `type(value) is ...` over `isinstance(...)` in _is_json_safe_scalar. + # With the isinstance form this value is retained and the record is dropped. + logger, buf = _make_json_logger("json-forged-class") + logger.info("before") + logger.info("survives a liar", extra={"request_id": _ForgedClassStr()}) + logger.info("after") + + messages = [ + json.loads(line)["message"] + for line in buf.getvalue().splitlines() + if line.strip() + ] + assert messages == ["before", "survives a liar", "after"] + + parsed = json.loads(buf.getvalue().splitlines()[1]) + assert parsed["level"] == "INFO" + assert "correlation_id" not in parsed + assert parsed["serialization_error"].startswith("RuntimeError") + + @pytest.mark.parametrize("value", [float("inf"), float("-inf"), float("nan")]) def test_non_finite_enrichment_does_not_produce_invalid_json(value): # Python's json emits the JavaScript literals NaN/Infinity for these, which From 209f1bef8ed6c98de1185ed70371c80debd61d73 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 21:02:02 +0000 Subject: [PATCH 4/4] test(logging): cover the nested-raise and traceback-survival paths Both salvaged from #1472, a competing implementation of #1452. They pass unmodified on this head, so they are pure coverage gain rather than a behaviour change. * An enrichment whose __str__ raises an exception that ITSELF raises when rendered. This is what makes _describe_exception's inner guard live code rather than defensive decoration -- the existing unit test calls the helper directly, which cannot show the path is reachable through the formatter. * A traceback must survive the fallback. `exception` is rendered to str before the guarded dump, so a poisoned enrichment firing the fallback must not also cost the traceback. With this, the branch carries the union of all four competing PRs: #1471's exact-type filter, #1472's two tests, and the non-finite float guard found by this run's red-team pass, which none of the others have. 32 passed. ruff clean. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_0146p7ZfxtbdEfJjtgETZTNf --- tests/unit/test_logging_config_crlf.py | 49 ++++++++++++++++++++++++++ 1 file changed, 49 insertions(+) diff --git a/tests/unit/test_logging_config_crlf.py b/tests/unit/test_logging_config_crlf.py index ea016f067..84eabf9cb 100644 --- a/tests/unit/test_logging_config_crlf.py +++ b/tests/unit/test_logging_config_crlf.py @@ -456,6 +456,55 @@ def test_finite_float_enrichment_is_kept(): 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 `_describe_exception`'s inner guard live code rather + than defensive decoration: the fallback renders the exception it caught, + and here that render raises again. + """ + + def __str__(self) -> str: + raise _ExplodingError() + + +def test_exception_whose_str_also_raises_does_not_lose_the_record(): + # Credit to #1471/#1472 for exercising this end-to-end; the helper's own + # unit test above cannot show the path is reachable through the formatter. + logger, buf = _make_json_logger("json-nested-exploding") + 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 also cost us the traceback. + logger, buf = _make_json_logger("json-fallback-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 + + def test_describe_exception_survives_an_exception_that_cannot_be_stringified(): # The fallback formats the error it caught. If that exception's own # __str__ raises, describing it must not re-raise and re-lose the record.