diff --git a/litellm/_logging.py b/litellm/_logging.py index 873a6619a81..5ba0c080364 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -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"(? 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 diff --git a/litellm/constants.py b/litellm/constants.py index 338fe0f6b85..8409a161800 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -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 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/litellm/litellm_core_utils/safe_json_dumps.py b/litellm/litellm_core_utils/safe_json_dumps.py index 5b99e8cba98..4f9ac82d57d 100644 --- a/litellm/litellm_core_utils/safe_json_dumps.py +++ b/litellm/litellm_core_utils/safe_json_dumps.py @@ -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) 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/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 57c39280a9f..7cecdaec25d 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -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.""" 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())