From 5fcbf91730ea67f8d93f5fb8cc4ee4d1cf927135 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Sat, 12 Sep 2026 19:17:26 -0700 Subject: [PATCH 1/8] fix(logging): scan each log record once and collapse base64 payloads before the secret regex Since #37391 every log record went through the secret-redaction regex twice, once in the filter and again in the formatter, and the formatter pass ran on the whole formatted line. At DEBUG level a multi-megabyte request body (a multi-page PDF upload to /v1/ocr) turned each of those lines into ten seconds of synchronous regex work on the event loop, long enough for a Kubernetes liveness probe to restart the pod mid-request. The filter is now the complete scrubber (message, exception text, stack info, and extras) and stamps the record, so the formatters skip records that are already clean. The stdout truncation filter also collapses base64 runs longer than MAX_BASE64_LENGTH_STDOUT_LOG (4096 by default) at every level before the secret regex sees them, so a debug line carrying a request body costs milliseconds instead of seconds. --- litellm/_logging.py | 100 ++++++++--- litellm/constants.py | 1 + litellm/litellm_core_utils/logging_utils.py | 17 +- .../litellm_core_utils/test_logging_utils.py | 10 +- tests/test_litellm/test_logging.py | 165 +++++++++++++++++- tests/test_litellm/test_secret_redaction.py | 6 +- 6 files changed, 249 insertions(+), 50 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index c73b5175a31..d2c1fe9039d 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -1,7 +1,10 @@ import ast import contextvars +import functools +import json import logging import os +import re import sys from datetime import datetime from logging import Formatter @@ -12,6 +15,7 @@ import litellm from litellm.constants import ( LITELLM_TRUNCATED_PAYLOAD_FIELD, LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE, + MAX_BASE64_LENGTH_STDOUT_LOG, MAX_STRING_LENGTH_STDOUT_LOG, ) from litellm.litellm_core_utils.env_utils import get_env_int @@ -76,6 +80,21 @@ def _redact_structured_value(key: str | None, value: str) -> str: return redact_structured_value(key, value) +_REDACTED_RECORD_ATTR: Final = "litellm_redacted" +_UNREDACTED_SCALAR_TYPES: Final = (bool, int, float, type(None)) + + +def _is_redacted(record: logging.LogRecord) -> bool: + return getattr(record, _REDACTED_RECORD_ATTR, False) is True + + +def _redact_extra_value(key: str, value: object) -> object: + try: + return json.loads(safe_dumps({key: value}, value_transform=_redact_structured_value))[key] + except (TypeError, ValueError, KeyError): + return _redact_string(str(value)) + + def redact_secrets(value: str) -> str: """Public API: redact known secret/credential patterns from an arbitrary string. @@ -148,11 +167,19 @@ class SecretRedactionFilter(logging.Filter): except Exception: pass + if isinstance(record.stack_info, str): + record.stack_info = _redact_string(record.stack_info) # rebind-ok: a Filter scrubs records in place + # Redact extra fields passed via logger.debug("msg", extra={...}) for key, value in list(record.__dict__.items()): - if key not in _STANDARD_RECORD_ATTRS and isinstance(value, str): - setattr(record, key, _redact_string(value)) + if key in _STANDARD_RECORD_ATTRS: + continue + if isinstance(value, str): + setattr(record, key, _redact_structured_value(key, value)) + elif not isinstance(value, _UNREDACTED_SCALAR_TYPES): + setattr(record, key, _redact_extra_value(key, value)) + setattr(record, _REDACTED_RECORD_ATTR, True) return True @@ -247,6 +274,37 @@ def _truncate_for_stdout_log(text: str, limit: int) -> str: return f"{text[:head_chars]}{_stdout_truncation_marker(len(text) - kept_chars)}{text[-tail_chars:]}" +_BYTES_PER_KIB: Final = 1024 +_BYTES_PER_MIB: Final = 1024 * 1024 + + +def format_base64_size(num_chars: int) -> str: + """Return a human-readable byte-size estimate from a base64 character count.""" + num_bytes: Final = num_chars * 3 / 4 + if num_bytes >= _BYTES_PER_MIB: + return f"{num_bytes / _BYTES_PER_MIB:.2f}MB" + if num_bytes >= _BYTES_PER_KIB: + return f"{num_bytes / _BYTES_PER_KIB:.1f}KB" + return f"{int(num_bytes)}B" + + +def _get_max_base64_length_stdout_log() -> int: + return get_env_int("MAX_BASE64_LENGTH_STDOUT_LOG", MAX_BASE64_LENGTH_STDOUT_LOG) + + +@functools.lru_cache(maxsize=8) +def _base64_run_pattern(min_chars: int) -> "re.Pattern[str]": + return re.compile(rf"(? str: + return f"[base64_data truncated: {format_base64_size(len(match.group(0)))}]" + + +def _collapse_base64_runs(text: str, limit: int) -> str: + return _base64_run_pattern(limit + 1).sub(_base64_run_placeholder, text) + + class StdoutLogTruncationFilter(logging.Filter): """Bounds how much of an oversized log line reaches stdout. @@ -254,31 +312,31 @@ class StdoutLogTruncationFilter(logging.Filter): request writes hundreds of KB to stdout, repeatedly as the exception propagates from the router to the proxy handler and into its traceback, all inline on the event loop. - DEBUG records pass through untouched, since dumping full payloads is the point of - `--detailed_debug`, and logging callbacks (OTEL, Datadog, etc.) don't run through - logging filters at all, so they still get the untruncated error. + At every level, a base64 run longer than MAX_BASE64_LENGTH_STDOUT_LOG collapses to a + size placeholder first: a multi-megabyte document upload otherwise costs seconds of + event-loop time per DEBUG line in the secret regex alone. The text around it stays, + since dumping payloads is the point of `--detailed_debug`, and logging callbacks + (OTEL, Datadog, etc.) don't run through logging filters at all, so they still get + the untouched record. """ _formatter = logging.Formatter() def filter(self, record: logging.LogRecord) -> bool: - if record.levelno < logging.INFO: - return True - - limit: Final = _get_max_string_length_stdout_log() - if limit <= 0: - return True - try: message: Final = record.getMessage() except (TypeError, ValueError): return True - if len(message) > limit: - record.msg = _truncate_for_stdout_log(message, limit) # rebind-ok: the Filter interface mutates the record - record.args = None # rebind-ok: args are consumed by the truncated message above + base64_limit: Final = _get_max_base64_length_stdout_log() + collapsed: Final = _collapse_base64_runs(message, base64_limit) if base64_limit > 0 else message + limit: Final = _get_max_string_length_stdout_log() if record.levelno >= logging.INFO else 0 + bounded: Final = _truncate_for_stdout_log(collapsed, limit) if 0 < limit < len(collapsed) else collapsed + if bounded != message: + record.msg = bounded # rebind-ok: the Filter interface mutates the record + record.args = None # rebind-ok: args are consumed by the rewritten message above - if isinstance(record.exc_info, tuple): + if limit > 0 and isinstance(record.exc_info, tuple): exc_text: Final = record.exc_text or self._formatter.formatException(record.exc_info) if len(exc_text) > limit: record.exc_text = _truncate_for_stdout_log( # rebind-ok: the Filter interface mutates the record @@ -440,6 +498,7 @@ def _get_standard_record_attrs() -> frozenset: _STANDARD_RECORD_ATTRS: Final = _get_standard_record_attrs() +_NON_EXTRA_RECORD_ATTRS: Final = _STANDARD_RECORD_ATTRS | {_REDACTED_RECORD_ATTR} # CorrelationContextFilter is the only legitimate source for these two JSON fields; # see JsonFormatter.format() for why they're excluded from the generic message-content @@ -480,7 +539,7 @@ class JsonFormatter(Formatter): # Include extra attributes passed via logger.debug("msg", extra={...}) for key, value in record.__dict__.items(): - if key not in _STANDARD_RECORD_ATTRS and key not in json_record: + if key not in _NON_EXTRA_RECORD_ATTRS and key not in json_record: json_record[key] = value # trace_id/session_id are reserved: CorrelationContextFilter is the only @@ -504,7 +563,7 @@ class JsonFormatter(Formatter): if record.exc_info: json_record["stacktrace"] = record.exc_text or self.formatException(record.exc_info) - return safe_dumps(json_record, value_transform=_redact_structured_value) + return safe_dumps(json_record, value_transform=None if _is_redacted(record) else _redact_structured_value) class CorrelationPlainFormatter(logging.Formatter): @@ -515,7 +574,8 @@ class CorrelationPlainFormatter(logging.Formatter): """ def format(self, record: logging.LogRecord) -> str: - formatted: Final = _redact_string(super().format(record)) + rendered: Final = super().format(record) + formatted: Final = rendered if _is_redacted(record) else _redact_string(rendered) trace_id: Final = getattr(record, "trace_id", None) session_id: Final = getattr(record, "session_id", None) if not trace_id and not session_id: @@ -533,8 +593,8 @@ def _setup_json_exception_handlers(formatter): # Create a handler with JSON formatting for exceptions error_handler: Final = logging.StreamHandler() error_handler.setFormatter(formatter) - error_handler.addFilter(_secret_filter) error_handler.addFilter(_stdout_truncation_filter) + error_handler.addFilter(_secret_filter) error_handler.addFilter(_correlation_filter) # Setup excepthook for uncaught exceptions diff --git a/litellm/constants.py b/litellm/constants.py index 6b984c2673c..e01f7d98f73 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -99,6 +99,7 @@ REDACTED_BY_LITELLM: Final = "redacted-by-litellm" REDACTED_TOOL_CALL_ARGUMENTS_PLACEHOLDER: Final = "{}" MAX_STRING_LENGTH_STDOUT_LOG: Final = get_env_int("MAX_STRING_LENGTH_STDOUT_LOG", 4096) +MAX_BASE64_LENGTH_STDOUT_LOG: Final = get_env_int("MAX_BASE64_LENGTH_STDOUT_LOG", 4096) # When true, adds detailed per-phase timing breakdown headers to responses. # Headers: x-litellm-timing-{pre-processing,llm-api,post-processing,message-copy}-ms diff --git a/litellm/litellm_core_utils/logging_utils.py b/litellm/litellm_core_utils/logging_utils.py index 44daef42e14..0f14b461d3d 100644 --- a/litellm/litellm_core_utils/logging_utils.py +++ b/litellm/litellm_core_utils/logging_utils.py @@ -7,7 +7,7 @@ from collections.abc import Iterator, Mapping, Sequence from datetime import datetime from typing import TYPE_CHECKING, Any, Final -from litellm._logging import verbose_logger +from litellm._logging import format_base64_size, verbose_logger from litellm.constants import ( BASE64_TRUNCATION_OFFLOAD_THRESHOLD_CHARS, MAX_BASE64_LENGTH_FOR_LOGGING, @@ -40,9 +40,6 @@ import litellm Helper utils used for logging callbacks """ -_BYTES_PER_KIB: Final = 1024 -_BYTES_PER_MIB: Final = 1024 * 1024 - # Regex matching data-URI base64 content: "data:;base64," # Captures: group(1)=mime_type, group(2)=base64_payload _DATA_URI_RE: Final = re.compile(r"data:([^;]+);base64,([A-Za-z0-9+/=]+)") @@ -52,23 +49,13 @@ _DATA_URI_RE: Final = re.compile(r"data:([^;]+);base64,([A-Za-z0-9+/=]+)") _MAX_TRUNCATION_DEPTH: Final = 20 -def _format_base64_size(num_chars: int) -> str: - """Return a human-readable byte-size estimate from a base64 character count.""" - num_bytes: Final = num_chars * 3 / 4 - if num_bytes >= _BYTES_PER_MIB: - return f"{num_bytes / _BYTES_PER_MIB:.2f}MB" - if num_bytes >= _BYTES_PER_KIB: - return f"{num_bytes / _BYTES_PER_KIB:.1f}KB" - return f"{int(num_bytes)}B" - - def _base64_data_uri_replacer(match: re.Match) -> str: """Replace a single base64 data-URI match with a size placeholder if too long.""" mime_type: Final = match.group(1) payload: Final = match.group(2) if len(payload) <= MAX_BASE64_LENGTH_FOR_LOGGING: return match.group(0) - size_str: Final = _format_base64_size(len(payload)) + size_str: Final = format_base64_size(len(payload)) return f"data:{mime_type};base64,[base64_data truncated: {size_str}]" diff --git a/tests/test_litellm/litellm_core_utils/test_logging_utils.py b/tests/test_litellm/litellm_core_utils/test_logging_utils.py index f9913f1935d..b446021a7dc 100644 --- a/tests/test_litellm/litellm_core_utils/test_logging_utils.py +++ b/tests/test_litellm/litellm_core_utils/test_logging_utils.py @@ -8,28 +8,28 @@ import pytest from litellm.litellm_core_utils import logging_utils from litellm.litellm_core_utils.logging_utils import ( - _format_base64_size, + format_base64_size, _truncate_base64_in_string, truncate_base64_in_messages, truncate_base64_in_messages_async, ) # --------------------------------------------------------------------------- -# _format_base64_size +# format_base64_size # --------------------------------------------------------------------------- class TestFormatBase64Size: def test_bytes_range(self): - assert _format_base64_size(4) == "3B" + assert format_base64_size(4) == "3B" def test_kb_range(self): # 2000 base64 chars ~ 1500 bytes ~ 1.5KB - assert "KB" in _format_base64_size(2000) + assert "KB" in format_base64_size(2000) def test_mb_range(self): # 2_000_000 base64 chars ~ 1.5MB - result = _format_base64_size(2_000_000) + result = format_base64_size(2_000_000) assert "MB" in result diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index bf3757e6886..81b0ecbcf5e 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1,5 +1,6 @@ import ast import asyncio +import base64 import json import logging import re @@ -40,6 +41,7 @@ from litellm._logging import ( ) from litellm.constants import LITELLM_TRUNCATED_PAYLOAD_FIELD from litellm.integrations.custom_logger import CustomLogger +from litellm.litellm_core_utils import secret_redaction from litellm.types.utils import StandardLoggingPayload @@ -685,10 +687,17 @@ def _make_record(level: int, msg: str, args=(), exc_info=None) -> logging.LogRec ) +def _oversized_text(length: int) -> str: + return ("payload " * (length // 8 + 1))[:length] + + +_OVERSIZED_TEXT = _oversized_text(100_000) + + def test_oversized_info_record_is_truncated(monkeypatch): """An error string echoing a huge request payload must not reach stdout in full.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - payload = "p" * 100_000 + payload = _OVERSIZED_TEXT record = _make_record(logging.INFO, "litellm.acompletion(model=%s) Exception %s", ("gpt-4", payload)) assert StdoutLogTruncationFilter().filter(record) is True @@ -696,8 +705,8 @@ def test_oversized_info_record_is_truncated(monkeypatch): message = record.getMessage() assert LITELLM_TRUNCATED_PAYLOAD_FIELD in message assert len(message) <= 500 - assert message.startswith("litellm.acompletion(model=gpt-4) Exception ppp") - assert message.endswith("ppp") + assert message.startswith("litellm.acompletion(model=gpt-4) Exception payload payload") + assert message.endswith("payload ") marker = _extract_marker(message) assert marker is not None @@ -721,7 +730,7 @@ def test_truncated_message_fits_the_configured_cap(monkeypatch): @pytest.mark.parametrize("payload_len", [501, 512, 1000, 9999, 100_000]) def test_truncated_message_never_exceeds_the_cap(monkeypatch, payload_len): monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - record = _make_record(logging.ERROR, "%s", ("p" * payload_len,)) + record = _make_record(logging.ERROR, "%s", (_oversized_text(payload_len),)) assert StdoutLogTruncationFilter().filter(record) is True @@ -747,7 +756,7 @@ def test_cap_leaving_no_room_for_the_marker_still_bounds_output(monkeypatch, cap def test_debug_record_is_not_truncated(monkeypatch): """--detailed_debug exists to dump full payloads, so DEBUG records pass through.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - payload = "p" * 100_000 + payload = _OVERSIZED_TEXT record = _make_record(logging.DEBUG, "raw request %s", (payload,)) assert StdoutLogTruncationFilter().filter(record) is True @@ -757,7 +766,7 @@ def test_debug_record_is_not_truncated(monkeypatch): def test_truncation_disabled_by_zero_limit(monkeypatch): monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "0") - payload = "p" * 100_000 + payload = _OVERSIZED_TEXT record = _make_record(logging.ERROR, "Exception %s", (payload,)) assert StdoutLogTruncationFilter().filter(record) is True @@ -785,7 +794,7 @@ def test_oversized_traceback_is_truncated(monkeypatch): def test_falsy_exc_info_is_not_formatted(monkeypatch): """Callers pass exc_info=False, which logging leaves on the record as a bool.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - record = _make_record(logging.WARNING, "skipping malformed endpoint %s", ("p" * 100_000,), exc_info=False) + record = _make_record(logging.WARNING, "skipping malformed endpoint %s", (_OVERSIZED_TEXT,), exc_info=False) assert StdoutLogTruncationFilter().filter(record) is True @@ -824,13 +833,153 @@ def test_oversized_error_is_truncated_end_to_end(monkeypatch, caplog): monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") with caplog.at_level(logging.INFO, logger="LiteLLM Router"): - verbose_router_logger.info("litellm.acompletion(model=%s) Exception %s", "gpt-4", "p" * 100_000) + verbose_router_logger.info("litellm.acompletion(model=%s) Exception %s", "gpt-4", _OVERSIZED_TEXT) emitted = "".join(record.getMessage() for record in caplog.records) assert LITELLM_TRUNCATED_PAYLOAD_FIELD in emitted assert len(emitted) <= 500 +_PDF_BASE64 = base64.b64encode(bytes(range(256)) * 18).decode() +_IMAGE_BASE64 = base64.b64encode(bytes(range(256)) * 24).decode() +_SHA256_HEX = "9f86d081884c7d659a2feaa0c55ad015a3bf4f1b2b0b822cd15d6c15b0f00a08" +_LIMIT_SIZED_TOKEN = "t" * 4096 + + +def test_debug_record_collapses_long_base64_runs(): + """A DEBUG line dumping a document upload keeps its text but not the megabytes of + base64, which cost seconds of event-loop time per line in the secret regex alone.""" + record = _make_record( + logging.DEBUG, + "receiving data: %s", + ( + f"{{'document': 'data:application/pdf;base64,{_PDF_BASE64}', " + f"'base64Source': '{_IMAGE_BASE64}', " + f"'sha256': '{_SHA256_HEX}', 'token': '{_LIMIT_SIZED_TOKEN}'}}", + ), + ) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == ( + "receiving data: {'document': 'data:application/pdf;base64,[base64_data truncated: 4.5KB]', " + "'base64Source': '[base64_data truncated: 6.0KB]', " + f"'sha256': '{_SHA256_HEX}', 'token': '{_LIMIT_SIZED_TOKEN}'}}" + ) + + +@pytest.mark.parametrize("run_length,collapses", ((4096, False), (4097, True))) +def test_base64_run_collapses_only_past_the_limit(run_length, collapses): + record = _make_record(logging.DEBUG, "%s", ("A" * run_length,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert ("[base64_data truncated: " in record.getMessage()) is collapses + + +@pytest.mark.parametrize("limit,collapses", (("0", False), ("100", True))) +def test_base64_collapse_limit_follows_the_env(monkeypatch, limit, collapses): + monkeypatch.setenv("MAX_BASE64_LENGTH_STDOUT_LOG", limit) + record = _make_record(logging.DEBUG, "%s", ("A" * 200,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert ("[base64_data truncated: " in record.getMessage()) is collapses + + +def test_info_record_collapses_base64_before_truncating(monkeypatch): + """The collapse runs at every level ahead of the INFO+ cap, so an error echoing a + document upload comes out as its text around a size placeholder, not a head and tail.""" + monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") + record = _make_record(logging.ERROR, "Exception: bad document %s (status 400)", ("A" * 100_000,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == "Exception: bad document [base64_data truncated: 73.2KB] (status 400)" + + +def test_base64_collapse_applies_end_to_end(caplog): + """The proxy's own request dump must come out collapsed, not just the filter in isolation.""" + with caplog.at_level(logging.DEBUG, logger="LiteLLM Proxy"): + verbose_proxy_logger.debug("receiving data: %s", f"{{'document': 'data:application/pdf;base64,{_PDF_BASE64}'}}") + + emitted = "".join(record.getMessage() for record in caplog.records) + assert emitted == "receiving data: {'document': 'data:application/pdf;base64,[base64_data truncated: 4.5KB]'}" + + +class _CountingPattern: + def __init__(self, pattern: "re.Pattern[str]"): + self._pattern = pattern + self.calls = 0 + self.scanned_chars = 0 + + def sub(self, repl: str, string: str, count: int = 0) -> str: + self.calls += 1 + self.scanned_chars += len(string) + return self._pattern.sub(repl, string, count) + + +_REQUEST_DUMP = "{'model': 'gpt-4', 'messages': [{'role': 'user', 'content': 'hello world'}]}" + + +@pytest.mark.parametrize( + "formatter", + (CorrelationPlainFormatter(_PLAIN_LOG_FORMAT), JsonFormatter()), + ids=("plain", "json"), +) +def test_scrubbed_record_is_scanned_for_secrets_once(monkeypatch, formatter): + """Every pass of the secret regex over a multi-megabyte debug line costs seconds of + event-loop time, so a formatter must not rescan what SecretRedactionFilter scrubbed.""" + 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 StdoutLogTruncationFilter().filter(record) is True + assert SecretRedactionFilter().filter(record) is True + rendered = formatter.format(record) + + assert _REQUEST_DUMP in rendered + assert "litellm_redacted" not in rendered + assert counting.calls == 1 + assert counting.scanned_chars == len(f"receiving data: {_REQUEST_DUMP}") + + +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") + record.stack_info = "Stack (most recent call last):\n api_key=sk-1234567890abcdefghij" + + assert SecretRedactionFilter().filter(record) is True + rendered = CorrelationPlainFormatter(_PLAIN_LOG_FORMAT).format(record) + + assert "sk-1234567890abcdefghij" not in rendered + assert "Stack (most recent call last):" in rendered + + +@pytest.mark.parametrize("extra", ({1, "a"}, {"nested": {1, "a"}}), ids=("mixed_set", "nested_mixed_set")) +def test_unserializable_extra_never_breaks_the_filter(monkeypatch, extra): + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = extra + + assert SecretRedactionFilter().filter(record) is True + rendered = json.loads(JsonFormatter().format(record)) + + assert rendered["message"] == "request sent" + assert "payload" in rendered + + +def test_unscrubbed_record_is_still_redacted_by_the_formatter(monkeypatch): + """Records that never met SecretRedactionFilter (uvicorn's, in JSON mode) keep + their formatter-side redaction.""" + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.INFO, "key sk-1234567890abcdefghij") + + assert "sk-1234567890abcdefghij" not in JsonFormatter().format(record) + assert "sk-1234567890abcdefghij" not in CorrelationPlainFormatter(_PLAIN_LOG_FORMAT).format(record) + + def test_set_session_id_bounds_length(): """set_session_id() must bound length so an oversized caller-supplied value isn't repeated across every log line for the request.""" diff --git a/tests/test_litellm/test_secret_redaction.py b/tests/test_litellm/test_secret_redaction.py index 9fa748edec1..85933fbf9e8 100644 --- a/tests/test_litellm/test_secret_redaction.py +++ b/tests/test_litellm/test_secret_redaction.py @@ -636,11 +636,13 @@ def test_aws_credential_redaction_catches_quoted_values(): {"blob": {"authorization": f"Bearer {SECRET}"}}, {"blob": [f"Bearer {SECRET}"]}, {"blob": ({"nested": {"deep": SECRET}},)}, + {"master_key": "opaque-value-with-no-pattern"}, ), - ids=("set", "dict", "list", "nested"), + ids=("set", "dict", "list", "nested", "key_name"), ) def test_json_formatter_redacts_non_string_extra_values(extra): - """SecretRedactionFilter only scrubs str attrs, so containers must be caught on render.""" + """Container extras and key-named str extras must come out scrubbed, whichever of the + filter and the formatter does the work.""" buf = StringIO() handler = logging.StreamHandler(buf) handler.setFormatter(JsonFormatter()) From 0d47d6ca58d89a4f58f42856c3d142e746bcb5d2 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Sat, 12 Sep 2026 19:42:45 -0700 Subject: [PATCH 2/8] fix(logging): collapse base64 runs in tracebacks and leave single-case runs alone Only mixed-case runs of the base64 alphabet collapse now, so a long hex digest, numeric id, or padding run stays in the debug line. The truncation filter also formats the traceback at every level and collapses base64 runs in it before the secret regex sees it, instead of only capping its length at INFO and above --- litellm/_logging.py | 43 +++++++++++++++++++----------- tests/test_litellm/test_logging.py | 41 +++++++++++++++++++++++++--- 2 files changed, 66 insertions(+), 18 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index d2c1fe9039d..2e89b1e4426 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -297,12 +297,20 @@ def _base64_run_pattern(min_chars: int) -> "re.Pattern[str]": return re.compile(rf"(? str: - return f"[base64_data truncated: {format_base64_size(len(match.group(0)))}]" +def _looks_like_base64(run: str) -> bool: + unpadded: Final = run.rstrip("=") + return not (unpadded.isdigit() or unpadded.islower() or unpadded.isupper()) + + +def _replace_base64_run(match: "re.Match[str]") -> str: + run: Final = match.group(0) + if not _looks_like_base64(run): + return run + return f"[base64_data truncated: {format_base64_size(len(run))}]" def _collapse_base64_runs(text: str, limit: int) -> str: - return _base64_run_pattern(limit + 1).sub(_base64_run_placeholder, text) + return _base64_run_pattern(limit + 1).sub(_replace_base64_run, text) class StdoutLogTruncationFilter(logging.Filter): @@ -312,12 +320,13 @@ class StdoutLogTruncationFilter(logging.Filter): request writes hundreds of KB to stdout, repeatedly as the exception propagates from the router to the proxy handler and into its traceback, all inline on the event loop. - At every level, a base64 run longer than MAX_BASE64_LENGTH_STDOUT_LOG collapses to a - size placeholder first: a multi-megabyte document upload otherwise costs seconds of - event-loop time per DEBUG line in the secret regex alone. The text around it stays, - since dumping payloads is the point of `--detailed_debug`, and logging callbacks - (OTEL, Datadog, etc.) don't run through logging filters at all, so they still get - the untouched record. + At every level, in the message and in the traceback alike, a mixed-case base64 run + longer than MAX_BASE64_LENGTH_STDOUT_LOG collapses to a size placeholder first: a + multi-megabyte document upload otherwise costs seconds of event-loop time per DEBUG + line in the secret regex alone. Single-case runs (hex digests, numeric ids, padding) + are left alone. The text around a run stays, since dumping payloads is the point of + `--detailed_debug`, and logging callbacks (OTEL, Datadog, etc.) don't run through + logging filters at all, so they still get the untouched record. """ _formatter = logging.Formatter() @@ -336,12 +345,16 @@ class StdoutLogTruncationFilter(logging.Filter): record.msg = bounded # rebind-ok: the Filter interface mutates the record record.args = None # rebind-ok: args are consumed by the rewritten message above - if limit > 0 and isinstance(record.exc_info, tuple): - exc_text: Final = record.exc_text or self._formatter.formatException(record.exc_info) - if len(exc_text) > limit: - record.exc_text = _truncate_for_stdout_log( # rebind-ok: the Filter interface mutates the record - exc_text, limit - ) + if not isinstance(record.exc_info, tuple): + return True + + exc_text: Final = record.exc_text or self._formatter.formatException(record.exc_info) + collapsed_exc: Final = _collapse_base64_runs(exc_text, base64_limit) if base64_limit > 0 else exc_text + bounded_exc: Final = ( + _truncate_for_stdout_log(collapsed_exc, limit) if 0 < limit < len(collapsed_exc) else collapsed_exc + ) + if bounded_exc != exc_text: + record.exc_text = bounded_exc # rebind-ok: the Filter interface mutates the record return True diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 81b0ecbcf5e..1f012edaa18 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -846,6 +846,10 @@ _SHA256_HEX = "9f86d081884c7d659a2feaa0c55ad015a3bf4f1b2b0b822cd15d6c15b0f00a08" _LIMIT_SIZED_TOKEN = "t" * 4096 +def _base64_run(length: int) -> str: + return (_PDF_BASE64 * (length // len(_PDF_BASE64) + 1))[:length] + + def test_debug_record_collapses_long_base64_runs(): """A DEBUG line dumping a document upload keeps its text but not the megabytes of base64, which cost seconds of event-loop time per line in the secret regex alone.""" @@ -870,7 +874,7 @@ def test_debug_record_collapses_long_base64_runs(): @pytest.mark.parametrize("run_length,collapses", ((4096, False), (4097, True))) def test_base64_run_collapses_only_past_the_limit(run_length, collapses): - record = _make_record(logging.DEBUG, "%s", ("A" * run_length,)) + record = _make_record(logging.DEBUG, "%s", (_base64_run(run_length),)) assert StdoutLogTruncationFilter().filter(record) is True @@ -880,7 +884,7 @@ def test_base64_run_collapses_only_past_the_limit(run_length, collapses): @pytest.mark.parametrize("limit,collapses", (("0", False), ("100", True))) def test_base64_collapse_limit_follows_the_env(monkeypatch, limit, collapses): monkeypatch.setenv("MAX_BASE64_LENGTH_STDOUT_LOG", limit) - record = _make_record(logging.DEBUG, "%s", ("A" * 200,)) + record = _make_record(logging.DEBUG, "%s", (_base64_run(200),)) assert StdoutLogTruncationFilter().filter(record) is True @@ -891,13 +895,44 @@ def test_info_record_collapses_base64_before_truncating(monkeypatch): """The collapse runs at every level ahead of the INFO+ cap, so an error echoing a document upload comes out as its text around a size placeholder, not a head and tail.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - record = _make_record(logging.ERROR, "Exception: bad document %s (status 400)", ("A" * 100_000,)) + record = _make_record(logging.ERROR, "Exception: bad document %s (status 400)", (_base64_run(100_000),)) assert StdoutLogTruncationFilter().filter(record) is True assert record.getMessage() == "Exception: bad document [base64_data truncated: 73.2KB] (status 400)" +@pytest.mark.parametrize( + "run", + (_SHA256_HEX * 80, "0123456789" * 512, "ABCDEFGHIJKLMNOP" * 320, "abcdefghijklmnop" * 320, "A" * 4097 + "=="), + ids=("hex", "digits", "upper", "lower", "padded_upper"), +) +def test_single_case_runs_are_not_mistaken_for_base64(run): + """A long hex digest, numeric id, or padding run stays in the log line: base64 of any + real payload mixes cases, so only mixed-case runs are collapsed and labeled base64.""" + record = _make_record(logging.DEBUG, "checksum %s", (run,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == f"checksum {run}" + + +def test_debug_traceback_collapses_base64_runs(): + """An exception that echoes a document upload gets the same collapse in its traceback + as the message does, at DEBUG too, so the secret regex never sees the payload in full.""" + try: + raise ValueError(f"bad document: {_base64_run(100_000)}") + except ValueError: + exc_info = sys.exc_info() + record = _make_record(logging.DEBUG, "call failed", exc_info=exc_info) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.exc_text is not None + assert "Traceback (most recent call last)" in record.exc_text + assert record.exc_text.endswith("ValueError: bad document: [base64_data truncated: 73.2KB]") + + def test_base64_collapse_applies_end_to_end(caplog): """The proxy's own request dump must come out collapsed, not just the filter in isolation.""" with caplog.at_level(logging.DEBUG, logger="LiteLLM Proxy"): From 74bc22c574e012516af1ca4174fbfbe7faa7cca3 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Sat, 12 Sep 2026 20:02:36 -0700 Subject: [PATCH 3/8] fix(logging): collapse constant-byte base64 payloads and keep only hex and decimal runs A run over MAX_BASE64_LENGTH_STDOUT_LOG now stays in the log line only when it is hex or decimal with at least two distinct characters. Collapsing only mixed-case runs let every constant-byte payload through: 0x00 encodes to AAAA, 0x01 to AQEB, 0x55 to VVVV, 0xAA to qqqq, so a zero-filled upload still paid the full secret regex. The two traceback tests that raised a 100,000-character run of one letter now raise the same text the other length-cap tests use, since a single-letter run is exactly the shape the collapse treats as a constant-byte payload --- litellm/_logging.py | 19 ++++++---- tests/test_litellm/test_logging.py | 58 +++++++++++++++++++----------- 2 files changed, 51 insertions(+), 26 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index 2e89b1e4426..5eb128cbf9e 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -297,9 +297,15 @@ def _base64_run_pattern(min_chars: int) -> "re.Pattern[str]": return re.compile(rf"(? bool: unpadded: Final = run.rstrip("=") - return not (unpadded.isdigit() or unpadded.islower() or unpadded.isupper()) + is_hex_or_decimal: Final = not unpadded.strip(_LOWER_HEX_DIGITS) or not unpadded.strip(_UPPER_HEX_DIGITS) + is_one_repeated_char: Final = not unpadded.strip(unpadded[0]) + return not is_hex_or_decimal or is_one_repeated_char def _replace_base64_run(match: "re.Match[str]") -> str: @@ -320,11 +326,12 @@ class StdoutLogTruncationFilter(logging.Filter): request writes hundreds of KB to stdout, repeatedly as the exception propagates from the router to the proxy handler and into its traceback, all inline on the event loop. - At every level, in the message and in the traceback alike, a mixed-case base64 run - longer than MAX_BASE64_LENGTH_STDOUT_LOG collapses to a size placeholder first: a - multi-megabyte document upload otherwise costs seconds of event-loop time per DEBUG - line in the secret regex alone. Single-case runs (hex digests, numeric ids, padding) - are left alone. The text around a run stays, since dumping payloads is the point of + At every level, in the message and in the traceback alike, a base64 run longer than + MAX_BASE64_LENGTH_STDOUT_LOG collapses to a size placeholder first: a multi-megabyte + document upload otherwise costs seconds of event-loop time per DEBUG line in the + secret regex alone. Hex and decimal runs (digests, numeric ids) are left alone unless + they are one repeated character, which is what a zero-filled payload encodes to. + The text around a run stays, since dumping payloads is the point of `--detailed_debug`, and logging callbacks (OTEL, Datadog, etc.) don't run through logging filters at all, so they still get the untouched record. """ diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 1f012edaa18..288f743dbad 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -17,6 +17,20 @@ from litellm._logging import ( _COLOR_LOG_FORMAT, _MAX_SCRUBBED_ACCESS_ARG, _PLAIN_LOG_FORMAT, + _get_uvicorn_json_log_config, + _initialize_loggers_with_handler, + _parse_json_logs_env, + _plain_log_format, + _stdout_truncation_marker, + _turn_on_json, + format_base64_size, + session_id_var, + set_session_id, + set_trace_id, + trace_id_var, + verbose_logger, + verbose_proxy_logger, + verbose_router_logger, ALL_LOGGERS, AccessLogRedactionFilter, CorrelationContextFilter, @@ -25,19 +39,6 @@ from litellm._logging import ( LevelRoutingStreamHandler, SecretRedactionFilter, StdoutLogTruncationFilter, - _get_uvicorn_json_log_config, - _initialize_loggers_with_handler, - _parse_json_logs_env, - _plain_log_format, - _stdout_truncation_marker, - _turn_on_json, - session_id_var, - set_session_id, - set_trace_id, - trace_id_var, - verbose_logger, - verbose_proxy_logger, - verbose_router_logger, ) from litellm.constants import LITELLM_TRUNCATED_PAYLOAD_FIELD from litellm.integrations.custom_logger import CustomLogger @@ -778,7 +779,7 @@ def test_oversized_traceback_is_truncated(monkeypatch): """verbose_proxy_logger.exception() re-logs the payload inside the traceback too.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") try: - raise ValueError("payload " + "p" * 100_000) + raise ValueError("payload " + _OVERSIZED_TEXT) except ValueError: exc_info = sys.exc_info() record = _make_record(logging.ERROR, "Exception occured", exc_info=exc_info) @@ -807,7 +808,7 @@ def test_secret_filter_keeps_truncated_traceback(monkeypatch): traceback instead of reformatting the full one from exc_info.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") try: - raise ValueError("sk-1234567890abcdefghij payload " + "p" * 100_000) + raise ValueError("sk-1234567890abcdefghij payload " + _OVERSIZED_TEXT) except ValueError: exc_info = sys.exc_info() record = _make_record(logging.ERROR, "Exception occured", exc_info=exc_info) @@ -904,12 +905,12 @@ def test_info_record_collapses_base64_before_truncating(monkeypatch): @pytest.mark.parametrize( "run", - (_SHA256_HEX * 80, "0123456789" * 512, "ABCDEFGHIJKLMNOP" * 320, "abcdefghijklmnop" * 320, "A" * 4097 + "=="), - ids=("hex", "digits", "upper", "lower", "padded_upper"), + (_SHA256_HEX * 80, _SHA256_HEX.upper() * 80, "0123456789" * 512, "0f" * 2100), + ids=("hex", "upper_hex", "digits", "two_char_hex_dump"), ) -def test_single_case_runs_are_not_mistaken_for_base64(run): - """A long hex digest, numeric id, or padding run stays in the log line: base64 of any - real payload mixes cases, so only mixed-case runs are collapsed and labeled base64.""" +def test_hex_and_decimal_runs_are_not_mistaken_for_base64(run): + """A long hex dump or numeric id stays in the log line even past the limit, since it + is not a payload and the operator asked for the full debug output.""" record = _make_record(logging.DEBUG, "checksum %s", (run,)) assert StdoutLogTruncationFilter().filter(record) is True @@ -917,6 +918,23 @@ def test_single_case_runs_are_not_mistaken_for_base64(run): assert record.getMessage() == f"checksum {run}" +@pytest.mark.parametrize( + "payload", + (bytes(6000), b"\x01" * 6000, b"\x55" * 6000, b"\xaa" * 6000), + ids=("zero_filled", "0x01_filled", "0x55_filled", "0xaa_filled"), +) +def test_constant_byte_payloads_still_collapse(payload): + """A zero-filled buffer encodes to one repeated character, and other constant bytes to + a single-case cycle: neither is a digest or an id, so the secret regex never sees them + in full and the event loop is not blocked by a degenerate upload.""" + encoded = base64.b64encode(payload).decode() + record = _make_record(logging.DEBUG, "upload %s", (encoded,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == f"upload [base64_data truncated: {format_base64_size(len(encoded))}]" + + def test_debug_traceback_collapses_base64_runs(): """An exception that echoes a document upload gets the same collapse in its traceback as the message does, at DEBUG too, so the secret regex never sees the payload in full.""" From 04eae3176905182eafb0b72b13089b459f345673 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Wed, 16 Sep 2026 14:17:48 -0700 Subject: [PATCH 4/8] fix(logging): keep secret-free log extras as their original objects A non-string extra was scrubbed by a safe_dumps round trip, which handed every user-attached handler a JSON-shaped copy even when nothing in it was redacted. The record now keeps the original object whenever the plain and the scrubbed renderings compare equal, so only an extra that carried a secret comes back as its scrubbed shape --- litellm/_logging.py | 4 ++- tests/test_litellm/test_logging.py | 49 ++++++++++++++++++++++++++++++ 2 files changed, 52 insertions(+), 1 deletion(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index 87d533b23fb..bcf77d65d96 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -90,7 +90,9 @@ def _is_redacted(record: logging.LogRecord) -> bool: def _redact_extra_value(key: str, value: object) -> object: try: - return json.loads(safe_dumps({key: value}, value_transform=_redact_structured_value))[key] + rendered: Final = safe_dumps({key: value}) + scrubbed: Final = safe_dumps({key: value}, value_transform=_redact_structured_value) + return value if scrubbed == rendered else json.loads(scrubbed)[key] except (TypeError, ValueError, KeyError): return _redact_string(str(value)) diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 12754ee4f27..43be8701b49 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1,6 +1,7 @@ import ast import asyncio import base64 +import dataclasses import json import logging import re @@ -1024,6 +1025,54 @@ def test_unserializable_extra_never_breaks_the_filter(monkeypatch, extra): assert "payload" in rendered +@dataclasses.dataclass(frozen=True, slots=True) +class _RequestExtra: + model: str + attempt: int + + +@pytest.mark.parametrize( + "extra", + ( + ("gpt-4o", 2), + {"gpt-4o", "gpt-4o-mini"}, + {"models": ("gpt-4o", "gpt-4o-mini")}, + _RequestExtra(model="gpt-4o", attempt=2), + ), + ids=("tuple", "set", "nested_tuple", "dataclass"), +) +def test_secret_free_extra_keeps_its_original_object(monkeypatch, extra): + """A host application's own handler on a litellm logger reads extras by type, so a + container that carried no secret must reach it untouched, not as its JSON shape.""" + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = extra + + assert SecretRedactionFilter().filter(record) is True + + assert record.payload is extra + assert "payload" in json.loads(JsonFormatter().format(record)) + + +@pytest.mark.parametrize( + "extra", + (("gpt-4o", "sk-1234567890abcdefghij"), {"gpt-4o", "sk-1234567890abcdefghij"}), + ids=("tuple", "set"), +) +def test_extra_that_carried_a_secret_comes_back_scrubbed(monkeypatch, extra): + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = extra + + assert SecretRedactionFilter().filter(record) is True + rendered = JsonFormatter().format(record) + + assert isinstance(record.payload, list) + assert sorted(record.payload) == ["REDACTED", "gpt-4o"] + assert "sk-1234567890abcdefghij" not in rendered + assert "REDACTED" in rendered + + def test_unscrubbed_record_is_still_redacted_by_the_formatter(monkeypatch): """Records that never met SecretRedactionFilter (uvicorn's, in JSON mode) keep their formatter-side redaction.""" From d5570d04d9ea39221d5bbe2257eafc9c8b424cb0 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Wed, 16 Sep 2026 15:07:22 -0700 Subject: [PATCH 5/8] fix(logging): keep a log extra only after inspecting every value it holds The filter kept an extra as its original object whenever the plain and scrubbed safe_dumps renderings matched, but safe_dumps skips what it cannot render (non-string dict keys, anything past its depth limit, fields a repr hides), so a secret in those places rode the untouched object past the litellm_redacted stamp. The filter now walks JSON-native shapes itself (strings, scalars, string-keyed dicts, lists and tuples) and keeps the original only when every value it holds comes back unchanged from the redactor; anything else is handed to safe_dumps and the record carries the scrubbed JSON shape the formatter would have rendered --- litellm/_logging.py | 21 ++++++++++-- tests/test_litellm/test_logging.py | 51 +++++++++++++++++++++++++++--- 2 files changed, 65 insertions(+), 7 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index bcf77d65d96..706ae0c8282 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -13,6 +13,7 @@ from urllib.parse import unquote import litellm from litellm.constants import ( + DEFAULT_MAX_RECURSE_DEPTH, LITELLM_TRUNCATED_PAYLOAD_FIELD, LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE, MAX_BASE64_LENGTH_STDOUT_LOG, @@ -88,11 +89,25 @@ def _is_redacted(record: logging.LogRecord) -> bool: return getattr(record, _REDACTED_RECORD_ATTR, False) is True +def _is_secret_free(key: str | None, value: object, depth: int) -> bool: + if depth > DEFAULT_MAX_RECURSE_DEPTH: + return False + if isinstance(value, str): + return _redact_structured_value(key, value) == value + if isinstance(value, _UNREDACTED_SCALAR_TYPES): + return True + if isinstance(value, dict): + return all(isinstance(k, str) and _is_secret_free(k, v, depth + 1) for k, v in value.items()) + if isinstance(value, (list, tuple)): + return all(_is_secret_free(key, item, depth + 1) for item in value) + return False + + def _redact_extra_value(key: str, value: object) -> object: + if _is_secret_free(key, value, 1): + return value try: - rendered: Final = safe_dumps({key: value}) - scrubbed: Final = safe_dumps({key: value}, value_transform=_redact_structured_value) - return value if scrubbed == rendered else json.loads(scrubbed)[key] + return json.loads(safe_dumps({key: value}, value_transform=_redact_structured_value))[key] except (TypeError, ValueError, KeyError): return _redact_string(str(value)) diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 43be8701b49..884c120f5c9 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1029,17 +1029,23 @@ def test_unserializable_extra_never_breaks_the_filter(monkeypatch, extra): class _RequestExtra: model: str attempt: int + api_key: str = dataclasses.field(default="", repr=False) + + +def _nest(value: object, levels: int) -> object: + return value if levels == 0 else _nest([value], levels - 1) @pytest.mark.parametrize( "extra", ( ("gpt-4o", 2), - {"gpt-4o", "gpt-4o-mini"}, - {"models": ("gpt-4o", "gpt-4o-mini")}, - _RequestExtra(model="gpt-4o", attempt=2), + ["gpt-4o", None, 1.5], + {"models": ("gpt-4o", "gpt-4o-mini"), "attempt": 2}, + {"model": "gpt-4o", "status": "ok"}, + _nest("gpt-4o", 99), ), - ids=("tuple", "set", "nested_tuple", "dataclass"), + ids=("tuple", "list", "nested_tuple", "dict", "deep_list"), ) def test_secret_free_extra_keeps_its_original_object(monkeypatch, extra): """A host application's own handler on a litellm logger reads extras by type, so a @@ -1073,6 +1079,43 @@ def test_extra_that_carried_a_secret_comes_back_scrubbed(monkeypatch, extra): assert "REDACTED" in rendered +@pytest.mark.parametrize( + "extra", + ( + {1: "sk-1234567890abcdefghij"}, + {"model": {1: "sk-1234567890abcdefghij"}}, + _nest("sk-1234567890abcdefghij", 101), + _RequestExtra(model="gpt-4o", attempt=2, api_key="sk-1234567890abcdefghij"), + {"gpt-4o", "sk-1234567890abcdefghij", 1}, + ), + ids=("int_key", "nested_int_key", "deeper_than_safe_dumps", "dataclass_hidden_field", "unsortable_set"), +) +def test_extra_the_filter_cannot_fully_inspect_never_keeps_its_secret(monkeypatch, extra): + """Whatever safe_dumps would skip (non-string keys, anything past its depth limit, + fields a repr hides) must not ride the original object past the redacted stamp.""" + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = extra + + assert SecretRedactionFilter().filter(record) is True + rendered = JsonFormatter().format(record) + + assert record.payload is not extra + assert "sk-1234567890abcdefghij" not in str(record.payload) + assert "sk-1234567890abcdefghij" not in rendered + + +def test_secret_free_set_comes_back_as_its_json_shape(monkeypatch): + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = {"gpt-4o", "gpt-4o-mini"} + + assert SecretRedactionFilter().filter(record) is True + + assert record.payload == ["gpt-4o", "gpt-4o-mini"] + assert json.loads(JsonFormatter().format(record))["payload"] == ["gpt-4o", "gpt-4o-mini"] + + def test_unscrubbed_record_is_still_redacted_by_the_formatter(monkeypatch): """Records that never met SecretRedactionFilter (uvicorn's, in JSON mode) keep their formatter-side redaction.""" From 2f186055e666f1c4339572115bda5291c8f6cec3 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Wed, 16 Sep 2026 16:29:23 -0700 Subject: [PATCH 6/8] fix(logging): decide keep-or-scrub for a log extra by comparing it to its scrubbed copy The code-quality check refuses recursive functions and the walk that inspected extras was one, so the filter no longer walks anything itself. safe_dumps now builds its JSON-native structure through safe_json_structure, the filter scrubs the extra through that, and the original object is kept only when the scrubbed copy compares equal to it. Anything the serializer skipped (non-string keys, nests past its depth, fields a repr hides) makes the copy differ, so the copy wins. A host object whose equality raises, as numpy arrays and torch tensors do, counts as changed instead of breaking the caller's log call --- litellm/_logging.py | 26 ++++-------- litellm/litellm_core_utils/safe_json_dumps.py | 22 +++++++--- .../test_safe_json_dumps.py | 13 +++++- tests/test_litellm/test_logging.py | 42 ++++++++++++++++--- 4 files changed, 72 insertions(+), 31 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index 706ae0c8282..d01960ed7ac 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -1,7 +1,6 @@ import ast import contextvars import functools -import json import logging import os import re @@ -13,14 +12,13 @@ from urllib.parse import unquote import litellm from litellm.constants import ( - DEFAULT_MAX_RECURSE_DEPTH, LITELLM_TRUNCATED_PAYLOAD_FIELD, LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE, MAX_BASE64_LENGTH_STDOUT_LOG, 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 +from litellm.litellm_core_utils.safe_json_dumps import 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, @@ -89,27 +87,19 @@ def _is_redacted(record: logging.LogRecord) -> bool: return getattr(record, _REDACTED_RECORD_ATTR, False) is True -def _is_secret_free(key: str | None, value: object, depth: int) -> bool: - if depth > DEFAULT_MAX_RECURSE_DEPTH: +def _scrubbing_changed_nothing(scrubbed: object, original: object) -> bool: + try: + return bool(scrubbed == original) + except Exception: return False - if isinstance(value, str): - return _redact_structured_value(key, value) == value - if isinstance(value, _UNREDACTED_SCALAR_TYPES): - return True - if isinstance(value, dict): - return all(isinstance(k, str) and _is_secret_free(k, v, depth + 1) for k, v in value.items()) - if isinstance(value, (list, tuple)): - return all(_is_secret_free(key, item, depth + 1) for item in value) - return False def _redact_extra_value(key: str, value: object) -> object: - if _is_secret_free(key, value, 1): - return value try: - return json.loads(safe_dumps({key: value}, value_transform=_redact_structured_value))[key] - except (TypeError, ValueError, KeyError): + scrubbed: Final = safe_json_structure(value, value_transform=_redact_structured_value, key=key) + except (TypeError, ValueError): return _redact_string(str(value)) + return value if _scrubbing_changed_nothing(scrubbed, value) else scrubbed def redact_secrets(value: str) -> str: diff --git a/litellm/litellm_core_utils/safe_json_dumps.py b/litellm/litellm_core_utils/safe_json_dumps.py index 5b99e8cba98..7cc47b2d6c3 100644 --- a/litellm/litellm_core_utils/safe_json_dumps.py +++ b/litellm/litellm_core_utils/safe_json_dumps.py @@ -12,19 +12,21 @@ def strip_null_bytes(value: str) -> str: return value.replace("\x00", "") -def safe_dumps( - data: Any, +def safe_json_structure( + data: object, max_depth: int = DEFAULT_MAX_RECURSE_DEPTH, value_transform: Callable[[str | None, str], str] | None = None, -) -> str: + key: str | None = None, +) -> object: """ - Recursively serialize data while detecting circular references. + Rebuild data out of JSON-native pieces while detecting circular references. If a circular reference is detected then a marker string is returned. NUL bytes are stripped from strings to prevent PostgreSQL 22P05 errors. value_transform, when given, is applied to every string leaf (and to the str() fallback for non-serializable objects) with the mapping key the leaf was reached under, so callers can rewrite values without touching structure. + key is the mapping key data itself was reached under, when the caller has one. """ def _transform(key: str | None, value: str) -> str: @@ -77,5 +79,13 @@ def safe_dumps( except Exception: return "Unserializable Object" - safe_data: Final = _serialize(data, set(), 0) - return json.dumps(safe_data, default=str) + return _serialize(data, set(), 0, key) + + +def safe_dumps( + data: Any, + max_depth: int = DEFAULT_MAX_RECURSE_DEPTH, + value_transform: Callable[[str | None, str], str] | None = None, +) -> str: + """Serialize data to JSON text through safe_json_structure.""" + return json.dumps(safe_json_structure(data, max_depth, value_transform), default=str) diff --git a/tests/test_litellm/litellm_core_utils/test_safe_json_dumps.py b/tests/test_litellm/litellm_core_utils/test_safe_json_dumps.py index 30385ba758d..1f2664f33cb 100644 --- a/tests/test_litellm/litellm_core_utils/test_safe_json_dumps.py +++ b/tests/test_litellm/litellm_core_utils/test_safe_json_dumps.py @@ -3,7 +3,7 @@ import json import pytest -from litellm.litellm_core_utils.safe_json_dumps import safe_dumps, strip_null_bytes +from litellm.litellm_core_utils.safe_json_dumps import safe_dumps, safe_json_structure, strip_null_bytes def test_primitive_types(): @@ -225,3 +225,14 @@ def test_pydantic_base_model(): assert len(result["healthy_endpoints"]) == 2 assert result["healthy_endpoints"][0]["name"] == "test" assert result["healthy_endpoints"][1] == {"value": 1, "label": "one"} + + +def test_safe_json_structure_keeps_tuples_and_drops_non_string_keys(): + data = {"models": ("a", "b"), "tags": {"y", "x"}, 1: "dropped", "nested": {"deep": ("c",)}} + + structure = safe_json_structure(data, value_transform=lambda key, value: value.upper()) + + assert isinstance(structure, dict) + assert structure == {"models": ("A", "B"), "tags": ["X", "Y"], "nested": {"deep": ("C",)}} + assert type(structure["models"]) is tuple + assert json.loads(safe_dumps(data)) == {"models": ["a", "b"], "tags": ["x", "y"], "nested": {"deep": ["c"]}} diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 884c120f5c9..18fb86e5a2a 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1061,11 +1061,15 @@ def test_secret_free_extra_keeps_its_original_object(monkeypatch, extra): @pytest.mark.parametrize( - "extra", - (("gpt-4o", "sk-1234567890abcdefghij"), {"gpt-4o", "sk-1234567890abcdefghij"}), - ids=("tuple", "set"), + "extra,scrubbed", + ( + (("gpt-4o", "sk-1234567890abcdefghij"), ("gpt-4o", "REDACTED")), + ({"gpt-4o", "sk-1234567890abcdefghij"}, ["REDACTED", "gpt-4o"]), + ({"model": "gpt-4o", "key": "sk-1234567890abcdefghij"}, {"model": "gpt-4o", "key": "REDACTED"}), + ), + ids=("tuple", "set", "dict"), ) -def test_extra_that_carried_a_secret_comes_back_scrubbed(monkeypatch, extra): +def test_extra_that_carried_a_secret_comes_back_scrubbed(monkeypatch, extra, scrubbed): monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) record = _make_record(logging.WARNING, "request sent") record.payload = extra @@ -1073,12 +1077,38 @@ def test_extra_that_carried_a_secret_comes_back_scrubbed(monkeypatch, extra): assert SecretRedactionFilter().filter(record) is True rendered = JsonFormatter().format(record) - assert isinstance(record.payload, list) - assert sorted(record.payload) == ["REDACTED", "gpt-4o"] + assert record.payload == scrubbed + assert type(record.payload) is type(scrubbed) assert "sk-1234567890abcdefghij" not in rendered assert "REDACTED" in rendered +class _AmbiguousArray: + def __eq__(self, other: object) -> bool: + raise ValueError("The truth value of an array with more than one element is ambiguous") + + def __repr__(self) -> str: + return "array([1, 2])" + + +@pytest.mark.parametrize( + "extra,scrubbed", + ((_AmbiguousArray(), "array([1, 2])"), ({"weights": _AmbiguousArray()}, {"weights": "array([1, 2])"})), + ids=("top_level", "nested"), +) +def test_extra_whose_equality_raises_still_comes_back_scrubbed(monkeypatch, extra, scrubbed): + """numpy arrays and torch tensors raise when compared for truth, so the keep-or-scrub + decision must fall on the scrubbed copy instead of breaking the caller's log call.""" + monkeypatch.setattr("litellm._logging._ENABLE_SECRET_REDACTION", True) + record = _make_record(logging.WARNING, "request sent") + record.payload = extra + + assert SecretRedactionFilter().filter(record) is True + + assert record.payload == scrubbed + assert json.loads(JsonFormatter().format(record))["payload"] == scrubbed + + @pytest.mark.parametrize( "extra", ( 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 7/8] 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 From 55cf4c43ed0b023eb3810aa3885552983a0dbee2 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Wed, 16 Sep 2026 17:30:49 -0700 Subject: [PATCH 8/8] fix(logging): stamp scrubbed records with a private sentinel a caller cannot supply A record stamped litellm_redacted=True skips the secret filter and both formatters, and extra={"litellm_redacted": True} on any log call put that stamp on a fresh record before the filter ran. The stamp is now a private object compared by identity, so only the filter's own pass marks a record scrubbed. --- litellm/_logging.py | 5 +++-- tests/test_litellm/test_logging.py | 17 +++++++++++++++++ 2 files changed, 20 insertions(+), 2 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index 28c5b4d8b46..f0fce8aa343 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -80,11 +80,12 @@ def _redact_structured_value(key: str | None, value: str) -> str: _REDACTED_RECORD_ATTR: Final = "litellm_redacted" +_REDACTED_STAMP: Final = object() _UNREDACTED_SCALAR_TYPES: Final = (bool, int, float, type(None)) def _is_redacted(record: logging.LogRecord) -> bool: - return getattr(record, _REDACTED_RECORD_ATTR, False) is True + return getattr(record, _REDACTED_RECORD_ATTR, None) is _REDACTED_STAMP def _scrubbing_changed_nothing(scrubbed: object, original: object) -> bool: @@ -193,7 +194,7 @@ class SecretRedactionFilter(logging.Filter): elif not isinstance(value, _UNREDACTED_SCALAR_TYPES): setattr(record, key, _redact_extra_value(key, value)) - setattr(record, _REDACTED_RECORD_ATTR, True) + setattr(record, _REDACTED_RECORD_ATTR, _REDACTED_STAMP) return True diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index eeb30f813bf..7cecdaec25d 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1015,6 +1015,23 @@ def test_stamped_record_is_not_scanned_again(monkeypatch): assert counting.calls == 1 +def test_caller_supplied_stamp_never_skips_the_scrub(monkeypatch): + """The stamp is a private sentinel, so a caller passing extra={"litellm_redacted": True} + still gets the full scrub, and only the filter's own stamp lets a later pass skip it.""" + 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, "api_key=sk-1234567890abcdefghij") + record.litellm_redacted = True + + assert SecretRedactionFilter().filter(record) is True + assert "sk-1234567890abcdefghij" not in record.getMessage() + assert counting.calls == 1 + + 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")