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.
This commit is contained in:
mateo-berri 2026-09-12 19:17:26 -07:00
parent d4a72e7372
commit 5fcbf91730
6 changed files with 249 additions and 50 deletions

View file

@ -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"(?<![A-Za-z0-9+/])[A-Za-z0-9+/]{{{min_chars},}}={{0,2}}")
def _base64_run_placeholder(match: "re.Match[str]") -> 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

View file

@ -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

View file

@ -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:<mime>;base64,<payload>"
# 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}]"

View file

@ -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

View file

@ -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."""

View file

@ -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())