diff --git a/litellm/_logging.py b/litellm/_logging.py index d2c1fe9039d..2e89b1e4426 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -297,12 +297,20 @@ def _base64_run_pattern(min_chars: int) -> "re.Pattern[str]": return re.compile(rf"(? str: - return f"[base64_data truncated: {format_base64_size(len(match.group(0)))}]" +def _looks_like_base64(run: str) -> bool: + unpadded: Final = run.rstrip("=") + return not (unpadded.isdigit() or unpadded.islower() or unpadded.isupper()) + + +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(_base64_run_placeholder, text) + return _base64_run_pattern(limit + 1).sub(_replace_base64_run, text) class StdoutLogTruncationFilter(logging.Filter): @@ -312,12 +320,13 @@ 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. - At every level, a base64 run longer than MAX_BASE64_LENGTH_STDOUT_LOG collapses to a - size placeholder first: a multi-megabyte document upload otherwise costs seconds of - event-loop time per DEBUG line in the secret regex alone. The text around it stays, - since dumping payloads is the point of `--detailed_debug`, and logging callbacks - (OTEL, Datadog, etc.) don't run through logging filters at all, so they still get - the untouched record. + At every level, in the message and in the traceback alike, a mixed-case 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. Single-case runs (hex digests, numeric ids, padding) + are left alone. 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 untouched record. """ _formatter = logging.Formatter() @@ -336,12 +345,16 @@ class StdoutLogTruncationFilter(logging.Filter): 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 limit > 0 and isinstance(record.exc_info, tuple): - exc_text: Final = record.exc_text or self._formatter.formatException(record.exc_info) - if len(exc_text) > limit: - record.exc_text = _truncate_for_stdout_log( # rebind-ok: the Filter interface mutates the record - 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 diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 81b0ecbcf5e..1f012edaa18 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -846,6 +846,10 @@ _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.""" @@ -870,7 +874,7 @@ def test_debug_record_collapses_long_base64_runs(): @pytest.mark.parametrize("run_length,collapses", ((4096, False), (4097, True))) def test_base64_run_collapses_only_past_the_limit(run_length, collapses): - record = _make_record(logging.DEBUG, "%s", ("A" * run_length,)) + record = _make_record(logging.DEBUG, "%s", (_base64_run(run_length),)) assert StdoutLogTruncationFilter().filter(record) is True @@ -880,7 +884,7 @@ def test_base64_run_collapses_only_past_the_limit(run_length, collapses): @pytest.mark.parametrize("limit,collapses", (("0", False), ("100", True))) def test_base64_collapse_limit_follows_the_env(monkeypatch, limit, collapses): monkeypatch.setenv("MAX_BASE64_LENGTH_STDOUT_LOG", limit) - record = _make_record(logging.DEBUG, "%s", ("A" * 200,)) + record = _make_record(logging.DEBUG, "%s", (_base64_run(200),)) assert StdoutLogTruncationFilter().filter(record) is True @@ -891,13 +895,44 @@ def test_info_record_collapses_base64_before_truncating(monkeypatch): """The collapse runs at every level ahead of the INFO+ cap, so an error echoing a document upload comes out as its text around a size placeholder, not a head and tail.""" monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500") - record = _make_record(logging.ERROR, "Exception: bad document %s (status 400)", ("A" * 100_000,)) + 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, "0123456789" * 512, "ABCDEFGHIJKLMNOP" * 320, "abcdefghijklmnop" * 320, "A" * 4097 + "=="), + ids=("hex", "digits", "upper", "lower", "padded_upper"), +) +def test_single_case_runs_are_not_mistaken_for_base64(run): + """A long hex digest, numeric id, or padding run stays in the log line: base64 of any + real payload mixes cases, so only mixed-case runs are collapsed and labeled base64.""" + record = _make_record(logging.DEBUG, "checksum %s", (run,)) + + assert StdoutLogTruncationFilter().filter(record) is True + + assert record.getMessage() == f"checksum {run}" + + +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"):