fix(logging): bound oversized error payloads written to stdout (#37684)

Co-authored-by: Yassin Kortam <yassin@berri.ai>

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

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

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