From c340046de22a70960cbea372f30bbd505025b996 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Wed, 16 Sep 2026 17:22:12 -0700 Subject: [PATCH] fix(logging): contain every extra serializer failure and skip rescanning a stamped record A pydantic model whose computed field raises escapes model_dump() and str() alike, and the secret filter caught only TypeError and ValueError, so the caller's own logger.warning() raised where the merge base contained the same failure inside the formatter. The scrub now catches every serializer failure and falls back to the object's text, or to the serializer's own "Unserializable Object" marker when even str() raises. JSON mode attaches the filter to uvicorn.error and the other third-party loggers and again to the root handler their records propagate to, so those records paid the secret regex twice. A record already stamped litellm_redacted now passes the filter untouched. --- litellm/_logging.py | 15 ++++++--- litellm/litellm_core_utils/safe_json_dumps.py | 4 ++- tests/test_litellm/test_logging.py | 32 ++++++++++++++++++- 3 files changed, 45 insertions(+), 6 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index d01960ed7ac..28c5b4d8b46 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -18,7 +18,7 @@ from litellm.constants import ( MAX_STRING_LENGTH_STDOUT_LOG, ) from litellm.litellm_core_utils.env_utils import get_env_int -from litellm.litellm_core_utils.safe_json_dumps import safe_dumps, safe_json_structure +from litellm.litellm_core_utils.safe_json_dumps import UNSERIALIZABLE_OBJECT, safe_dumps, safe_json_structure from litellm.litellm_core_utils.safe_json_loads import safe_json_loads from litellm.litellm_core_utils.secret_redaction import ( redact_internal_details, @@ -94,11 +94,18 @@ def _scrubbing_changed_nothing(scrubbed: object, original: object) -> bool: return False +def _plain_text(value: object) -> str: + try: + return str(value) + except Exception: + return UNSERIALIZABLE_OBJECT + + def _redact_extra_value(key: str, value: object) -> object: try: scrubbed: Final = safe_json_structure(value, value_transform=_redact_structured_value, key=key) - except (TypeError, ValueError): - return _redact_string(str(value)) + except Exception: + return _redact_string(_plain_text(value)) return value if _scrubbing_changed_nothing(scrubbed, value) else scrubbed @@ -151,7 +158,7 @@ class SecretRedactionFilter(logging.Filter): _formatter = logging.Formatter() def filter(self, record: logging.LogRecord) -> bool: - if not _ENABLE_SECRET_REDACTION: + if not _ENABLE_SECRET_REDACTION or _is_redacted(record): return True # Runs before args are cleared, and before the extra-field loop below diff --git a/litellm/litellm_core_utils/safe_json_dumps.py b/litellm/litellm_core_utils/safe_json_dumps.py index 7cc47b2d6c3..4f9ac82d57d 100644 --- a/litellm/litellm_core_utils/safe_json_dumps.py +++ b/litellm/litellm_core_utils/safe_json_dumps.py @@ -6,6 +6,8 @@ from pydantic import BaseModel from litellm.constants import DEFAULT_MAX_RECURSE_DEPTH +UNSERIALIZABLE_OBJECT: Final = "Unserializable Object" + def strip_null_bytes(value: str) -> str: """Strip NUL bytes, which PostgreSQL text/jsonb columns reject (error 22P05).""" @@ -77,7 +79,7 @@ def safe_json_structure( try: return _transform(key, strip_null_bytes(str(obj))) except Exception: - return "Unserializable Object" + return UNSERIALIZABLE_OBJECT return _serialize(data, set(), 0, key) diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 18fb86e5a2a..eeb30f813bf 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -12,6 +12,7 @@ from pathlib import Path from typing import List import pytest +from pydantic import BaseModel, computed_field import litellm from litellm._logging import ( @@ -1000,6 +1001,20 @@ def test_scrubbed_record_is_scanned_for_secrets_once(monkeypatch, formatter): assert counting.scanned_chars == len(f"receiving data: {_REQUEST_DUMP}") +def test_stamped_record_is_not_scanned_again(monkeypatch): + """JSON mode puts the filter on a third-party logger and again on the root handler its + records propagate to, so the second filter must trust the stamp instead of rescanning.""" + counting = _CountingPattern(secret_redaction._SECRET_RE) + monkeypatch.setattr(secret_redaction, "_SECRET_RE", counting) + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.DEBUG, "receiving data: %s", (_REQUEST_DUMP,)) + + assert SecretRedactionFilter().filter(record) is True + assert SecretRedactionFilter().filter(record) is True + + assert counting.calls == 1 + + def test_stack_info_is_scrubbed_before_the_plain_formatter(monkeypatch): monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) record = _make_record(logging.INFO, "call failed") @@ -1012,8 +1027,23 @@ def test_stack_info_is_scrubbed_before_the_plain_formatter(monkeypatch): assert "Stack (most recent call last):" in rendered -@pytest.mark.parametrize("extra", ({1, "a"}, {"nested": {1, "a"}}), ids=("mixed_set", "nested_mixed_set")) +class _BrokenModel(BaseModel): + name: str + + @computed_field + @property + def snapshot(self) -> str: + raise RuntimeError("snapshot unavailable") + + +@pytest.mark.parametrize( + "extra", + ({1, "a"}, {"nested": {1, "a"}}, _BrokenModel(name="gpt-4o"), {"request": _BrokenModel(name="gpt-4o")}), + ids=("mixed_set", "nested_mixed_set", "raising_model", "nested_raising_model"), +) def test_unserializable_extra_never_breaks_the_filter(monkeypatch, extra): + """A pydantic computed field that raises escapes model_dump() and str() alike, and a + logging filter that lets it through raises into the caller's own log call.""" monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) record = _make_record(logging.WARNING, "request sent") record.payload = extra