Merge pull request #40934 from BerriAI/litellm_fix_ocr_native_multipage_pdf

fix(logging): scan each log record once and collapse base64 payloads before the secret regex
This commit is contained in:
Mateo Wang 2026-09-16 18:06:11 -07:00 committed by GitHub
commit 2445bdd2b5
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
8 changed files with 557 additions and 79 deletions

View file

@ -3,6 +3,7 @@ import contextvars
import functools
import logging
import os
import re
import sys
from datetime import datetime
from logging import Formatter
@ -13,10 +14,11 @@ 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
from litellm.litellm_core_utils.safe_json_dumps import safe_dumps
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,
@ -77,6 +79,37 @@ def _redact_structured_value(key: str | None, value: str) -> str:
return redact_structured_value(key, value)
_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, None) is _REDACTED_STAMP
def _scrubbing_changed_nothing(scrubbed: object, original: object) -> bool:
try:
return bool(scrubbed == original)
except Exception:
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 Exception:
return _redact_string(_plain_text(value))
return value if _scrubbing_changed_nothing(scrubbed, value) else scrubbed
def redact_secrets(value: str) -> str:
"""Public API: redact known secret/credential patterns from an arbitrary string.
@ -126,7 +159,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
@ -149,11 +182,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, _REDACTED_STAMP)
return True
@ -277,6 +318,51 @@ 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}}")
_LOWER_HEX_DIGITS: Final = "0123456789abcdef"
_UPPER_HEX_DIGITS: Final = "0123456789ABCDEF"
def _looks_like_base64(run: str) -> bool:
unpadded: Final = run.rstrip("=")
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:
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(_replace_base64_run, text)
class StdoutLogTruncationFilter(logging.Filter):
"""Bounds how much of an oversized log line reaches stdout.
@ -284,36 +370,42 @@ 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
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 untruncated error.
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):
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
@ -474,6 +566,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
@ -514,7 +607,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
@ -538,7 +631,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):
@ -549,7 +642,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:
@ -567,8 +661,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

@ -102,6 +102,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

@ -6,25 +6,29 @@ 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)."""
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:
@ -75,7 +79,15 @@ def safe_dumps(
try:
return _transform(key, strip_null_bytes(str(obj)))
except Exception:
return "Unserializable Object"
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)

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

@ -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"]}}

View file

@ -1,5 +1,7 @@
import ast
import asyncio
import base64
import dataclasses
import json
import logging
import re
@ -10,12 +12,27 @@ from pathlib import Path
from typing import List
import pytest
from pydantic import BaseModel, computed_field
import litellm
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,
AccessLogPathFilter,
AccessLogRedactionFilter,
@ -25,22 +42,10 @@ 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
from litellm.litellm_core_utils import secret_redaction
from litellm.types.utils import StandardLoggingPayload
@ -686,10 +691,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
@ -697,8 +709,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
@ -722,7 +734,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
@ -748,7 +760,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
@ -758,7 +770,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
@ -770,7 +782,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)
@ -786,7 +798,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
@ -799,7 +811,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)
@ -825,13 +837,372 @@ 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 _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."""
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", (_base64_run(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", (_base64_run(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)", (_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, _SHA256_HEX.upper() * 80, "0123456789" * 512, "0f" * 2100),
ids=("hex", "upper_hex", "digits", "two_char_hex_dump"),
)
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
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."""
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"):
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_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_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")
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
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
assert SecretRedactionFilter().filter(record) is True
rendered = json.loads(JsonFormatter().format(record))
assert rendered["message"] == "request sent"
assert "payload" in rendered
@dataclasses.dataclass(frozen=True, slots=True)
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", None, 1.5],
{"models": ("gpt-4o", "gpt-4o-mini"), "attempt": 2},
{"model": "gpt-4o", "status": "ok"},
_nest("gpt-4o", 99),
),
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
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,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, scrubbed):
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 == 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",
(
{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."""
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())