fix(logging): collapse base64 runs in tracebacks and leave single-case runs alone

Only mixed-case runs of the base64 alphabet collapse now, so a long hex digest,
numeric id, or padding run stays in the debug line. The truncation filter also
formats the traceback at every level and collapses base64 runs in it before the
secret regex sees it, instead of only capping its length at INFO and above
This commit is contained in:
mateo-berri 2026-09-12 19:42:45 -07:00
parent 5fcbf91730
commit 0d47d6ca58
2 changed files with 66 additions and 18 deletions

View file

@ -297,12 +297,20 @@ 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}}")
def _base64_run_placeholder(match: "re.Match[str]") -> 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

View file

@ -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"):