diff --git a/litellm/_logging.py b/litellm/_logging.py index 7d3a30c6d1a..e55c6bc40a8 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -8,6 +8,12 @@ from logging import Formatter from typing import Any, Final import litellm +from litellm.constants import ( + LITELLM_TRUNCATED_PAYLOAD_FIELD, + LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE, + 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_loads import safe_json_loads from litellm.litellm_core_utils.secret_redaction import redact_string, redact_structured_value @@ -101,7 +107,7 @@ class SecretRedactionFilter(logging.Filter): # Redact exception tracebacks if record.exc_info and record.exc_info[1] is not None: try: - record.exc_text = _redact_string(self._formatter.formatException(record.exc_info)) + record.exc_text = _redact_string(record.exc_text or self._formatter.formatException(record.exc_info)) except Exception: pass @@ -116,6 +122,72 @@ class SecretRedactionFilter(logging.Filter): _secret_filter: Final = SecretRedactionFilter() +def _get_max_string_length_stdout_log() -> int: + """Read the limit per record so a value loaded later via proxy config + environment_variables is honored.""" + return get_env_int("MAX_STRING_LENGTH_STDOUT_LOG", MAX_STRING_LENGTH_STDOUT_LOG) + + +def _stdout_truncation_marker(skipped_chars: int) -> str: + return ( + f"... ({LITELLM_TRUNCATED_PAYLOAD_FIELD} skipped {skipped_chars} chars. " + f"{LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE}) ..." + ) + + +def _truncate_for_stdout_log(text: str, limit: int) -> str: + kept_chars: Final = limit - len(_stdout_truncation_marker(len(text))) + if kept_chars <= 0: + return text[:limit] + head_chars: Final = kept_chars // 2 + tail_chars: Final = kept_chars - head_chars + return f"{text[:head_chars]}{_stdout_truncation_marker(len(text) - kept_chars)}{text[-tail_chars:]}" + + +class StdoutLogTruncationFilter(logging.Filter): + """Bounds how much of an oversized log line reaches stdout. + + A provider error string can echo the whole request payload, so one failed agentic + 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. + """ + + _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 + + 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 + ) + + return True + + +_stdout_truncation_filter: Final = StdoutLogTruncationFilter() + + class CorrelationContextFilter(logging.Filter): """Stamps each log record with the current request's trace_id and session_id from contextvars. @@ -301,6 +373,7 @@ def _setup_json_exception_handlers(formatter): error_handler: Final = logging.StreamHandler() error_handler.setFormatter(formatter) error_handler.addFilter(_secret_filter) + error_handler.addFilter(_stdout_truncation_filter) error_handler.addFilter(_correlation_filter) # Setup excepthook for uncaught exceptions @@ -365,6 +438,12 @@ verbose_router_logger.addHandler(handler) verbose_proxy_logger.addHandler(handler) verbose_logger.addHandler(handler) +# Filters attached to the logger, not the handler, survive callers swapping in their own +# handlers (JSON mode, uvicorn log config, a host app's root handler). +verbose_router_logger.addFilter(_stdout_truncation_filter) +verbose_proxy_logger.addFilter(_stdout_truncation_filter) +verbose_logger.addFilter(_stdout_truncation_filter) + def _suppress_loggers(): """Suppress noisy loggers at INFO level""" diff --git a/litellm/constants.py b/litellm/constants.py index 0657d89529f..cf77e7c55db 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -49,6 +49,8 @@ LITELLM_MAX_STREAMING_DURATION_SECONDS: Final = ( # Set to 0 to disable truncation. MAX_BASE64_LENGTH_FOR_LOGGING: Final = int(os.getenv("MAX_BASE64_LENGTH_FOR_LOGGING", 64)) +MAX_STRING_LENGTH_STDOUT_LOG: Final = get_env_int("MAX_STRING_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 LITELLM_DETAILED_TIMING: Final = os.getenv("LITELLM_DETAILED_TIMING", "false").lower() == "true" @@ -1345,6 +1347,11 @@ LITELLM_TRUNCATION_DB_SAFEGUARD_NOTE: Final = ( "Full, untruncated data is logged to logging callbacks (OTEL, Datadog, etc.). " "To increase the truncation limit, set `MAX_STRING_LENGTH_PROMPT_IN_DB` in your env." ) +LITELLM_TRUNCATION_STDOUT_SAFEGUARD_NOTE: Final = ( + "Truncation is a stdout logging safeguard. " + "Full, untruncated data is logged to logging callbacks (OTEL, Datadog, etc.) and at DEBUG level. " + "To increase the truncation limit, set `MAX_STRING_LENGTH_STDOUT_LOG` in your env." +) ########################### LiteLLM Proxy Specific Constants ########################### ######################################################################################## diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 784ec5b6cf4..8551085cbd6 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -2,15 +2,14 @@ import ast import asyncio import json import os +import re import sys from pathlib import Path from typing import List import pytest -sys.path.insert( - 0, os.path.abspath("../../..") -) # Adds the parent directory to the system-path +sys.path.insert(0, os.path.abspath("../../..")) # Adds the parent directory to the system-path import logging import sys @@ -20,7 +19,10 @@ from litellm._logging import ( CorrelationContextFilter, CorrelationPlainFormatter, JsonFormatter, + SecretRedactionFilter, + StdoutLogTruncationFilter, _initialize_loggers_with_handler, + _stdout_truncation_marker, _turn_on_json, session_id_var, set_session_id, @@ -30,6 +32,7 @@ from litellm._logging import ( verbose_proxy_logger, verbose_router_logger, ) +from litellm.constants import LITELLM_TRUNCATED_PAYLOAD_FIELD from litellm.integrations.custom_logger import CustomLogger from litellm.types.utils import StandardLoggingPayload @@ -238,9 +241,7 @@ def test_json_formatter_includes_component_field(): ) output = formatter.format(record) obj = json.loads(output) - assert ( - obj["component"] == logger_name - ), f"Expected component={logger_name!r}, got {obj.get('component')!r}" + assert obj["component"] == logger_name, f"Expected component={logger_name!r}, got {obj.get('component')!r}" def test_json_formatter_includes_logger_field(): @@ -260,9 +261,7 @@ def test_json_formatter_includes_logger_field(): ) output = formatter.format(record) obj = json.loads(output) - assert ( - obj["logger"] == "proxy_server.py:123" - ), f"Expected logger='proxy_server.py:123', got {obj['logger']!r}" + assert obj["logger"] == "proxy_server.py:123", f"Expected logger='proxy_server.py:123', got {obj['logger']!r}" def test_json_formatter_extra_component_not_overwritten(): @@ -281,9 +280,7 @@ def test_json_formatter_extra_component_not_overwritten(): ) record.component = "auth-service" obj = json.loads(formatter.format(record)) - assert ( - obj["component"] == "auth-service" - ), f"User-supplied component was overwritten, got {obj['component']!r}" + assert obj["component"] == "auth-service", f"User-supplied component was overwritten, got {obj['component']!r}" def test_initialize_loggers_with_handler_sets_propagate_false(): @@ -295,9 +292,9 @@ def test_initialize_loggers_with_handler_sets_propagate_false(): # Check that propagate is set to False for all loggers for logger in ALL_LOGGERS: - assert ( - logger.propagate is False - ), f"Logger {logger.name} has propagate set to {logger.propagate}, expected False" + assert logger.propagate is False, ( + f"Logger {logger.name} has propagate set to {logger.propagate}, expected False" + ) @pytest.mark.asyncio @@ -335,9 +332,9 @@ async def test_cache_hit_includes_custom_llm_provider(): await asyncio.sleep(0.5) # Verify we have logged events - assert ( - len(test_custom_logger.logged_standard_logging_payloads) >= 2 - ), f"Expected at least 2 logged events, got {len(test_custom_logger.logged_standard_logging_payloads)}" + assert len(test_custom_logger.logged_standard_logging_payloads) >= 2, ( + f"Expected at least 2 logged events, got {len(test_custom_logger.logged_standard_logging_payloads)}" + ) # Find the cache hit event (should be the second call) cache_hit_payload = None @@ -347,20 +344,18 @@ async def test_cache_hit_includes_custom_llm_provider(): break # Verify cache hit event was found - assert ( - cache_hit_payload is not None - ), "No cache hit event found in logged payloads" + assert cache_hit_payload is not None, "No cache hit event found in logged payloads" # Verify custom_llm_provider is included in the cache hit payload - assert ( - "custom_llm_provider" in cache_hit_payload - ), "custom_llm_provider missing from cache hit standard logging payload" + assert "custom_llm_provider" in cache_hit_payload, ( + "custom_llm_provider missing from cache hit standard logging payload" + ) # Verify custom_llm_provider has a valid value (should be "openai" for gpt-3.5-turbo) custom_llm_provider = cache_hit_payload["custom_llm_provider"] - assert ( - custom_llm_provider is not None and custom_llm_provider != "" - ), f"custom_llm_provider should not be None or empty, got: {custom_llm_provider}" + assert custom_llm_provider is not None and custom_llm_provider != "", ( + f"custom_llm_provider should not be None or empty, got: {custom_llm_provider}" + ) print( f"Cache hit standard logging payload with custom_llm_provider: {custom_llm_provider}", @@ -666,6 +661,171 @@ def test_set_trace_id_strips_control_characters(): trace_id_var.reset(token) +_MARKER_RE = re.compile(rf"\.\.\. \({LITELLM_TRUNCATED_PAYLOAD_FIELD} skipped (\d+) chars\..*?\) \.\.\.", re.S) + + +def _extract_marker(text: str) -> "re.Match[str] | None": + return _MARKER_RE.search(text) + + +def _make_record(level: int, msg: str, args=(), exc_info=None) -> logging.LogRecord: + return logging.LogRecord( + name="LiteLLM Router", + level=level, + pathname="", + lineno=0, + msg=msg, + args=args, + exc_info=exc_info, + ) + + +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 + record = _make_record(logging.INFO, "litellm.acompletion(model=%s) Exception %s", ("gpt-4", payload)) + + assert StdoutLogTruncationFilter().filter(record) is True + + 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") + + marker = _extract_marker(message) + assert marker is not None + kept, skipped = len(message) - len(marker.group(0)), int(marker.group(1)) + assert kept + skipped == 43 + len(payload) + + +def test_truncated_message_fits_the_configured_cap(monkeypatch): + """The cap is the whole point of the setting, so the marker has to be paid for out of + the budget instead of appended on top of a limit-sized head and tail.""" + monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") + record = _make_record(logging.ERROR, "Exception %s", ("p" * 2000,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + message = record.getMessage() + assert _extract_marker(message) is not None + assert len(message) == 500 + + +@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,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert len(record.getMessage()) <= 500 + + +_NO_BUDGET_PAYLOAD = "p" * 2000 +_MARKER_SIZED_CAP = len(_stdout_truncation_marker(len(_NO_BUDGET_PAYLOAD))) + + +@pytest.mark.parametrize("cap", [_MARKER_SIZED_CAP, _MARKER_SIZED_CAP - 1, 100]) +def test_cap_leaving_no_room_for_the_marker_still_bounds_output(monkeypatch, cap): + """An operator can set the cap at or below the marker's own length, leaving nothing to + spend on a head and tail, and the output still has to fit.""" + monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", str(cap)) + record = _make_record(logging.ERROR, "%s", (_NO_BUDGET_PAYLOAD,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert len(record.getMessage()) == 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 + record = _make_record(logging.DEBUG, "raw request %s", (payload,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == f"raw request {payload}" + + +def test_truncation_disabled_by_zero_limit(monkeypatch): + monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "0") + payload = "p" * 100_000 + record = _make_record(logging.ERROR, "Exception %s", (payload,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == f"Exception {payload}" + + +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) + except ValueError: + exc_info = sys.exc_info() + record = _make_record(logging.ERROR, "Exception occured", exc_info=exc_info) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.exc_text is not None + assert LITELLM_TRUNCATED_PAYLOAD_FIELD in record.exc_text + assert len(record.exc_text) <= 500 + assert "Traceback (most recent call last)" in record.exc_text + + +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) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.exc_text is None + assert LITELLM_TRUNCATED_PAYLOAD_FIELD in record.getMessage() + + +def test_secret_filter_keeps_truncated_traceback(monkeypatch): + """SecretRedactionFilter runs after truncation, so it must redact the capped + 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) + except ValueError: + exc_info = sys.exc_info() + record = _make_record(logging.ERROR, "Exception occured", exc_info=exc_info) + + assert StdoutLogTruncationFilter().filter(record) is True + assert SecretRedactionFilter().filter(record) is True + + assert record.exc_text is not None + assert len(record.exc_text) <= 500 + assert "sk-1234567890abcdefghij" not in record.exc_text + + +def test_truncation_filter_survives_json_reconfiguration(): + """The cap lives on the loggers, so swapping handlers (JSON mode) can't drop it.""" + _turn_on_json() + + for lg in (verbose_logger, verbose_router_logger, verbose_proxy_logger): + assert any(isinstance(f, StdoutLogTruncationFilter) for f in lg.filters), f"{lg.name} lost stdout truncation" + + +def test_oversized_error_is_truncated_end_to_end(monkeypatch, caplog): + """The router's own exception log line must come out bounded, not just the filter in isolation.""" + 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) + + emitted = "".join(record.getMessage() for record in caplog.records) + assert LITELLM_TRUNCATED_PAYLOAD_FIELD in emitted + assert len(emitted) <= 500 + + 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.""" @@ -674,4 +834,3 @@ def test_set_session_id_bounds_length(): assert len(session_id_var.get()) == 256 finally: session_id_var.reset(token) -