From 66b930b5404e5c7b496aad41e190106a674dfdfd Mon Sep 17 00:00:00 2001 From: mubashir1osmani Date: Fri, 21 Aug 2026 19:04:53 -0400 Subject: [PATCH] fix(logging): preserve uvicorn color_message args during secret redaction (#37122) * fix(logging): preserve uvicorn color_message args during secret redaction SecretRedactionFilter clears record.args after substituting record.msg, but uvicorn's colorized formatter re-renders the separate color_message extra field against record.args at emit time. With args cleared, uvicorn prints the raw "%s://%s:%d" template instead of the actual startup URL whenever output goes to a TTY (colors on). * fix(logging): narrow color_message fallback to TypeError Bare except-Exception-pass on the color_message substitution pushed the BLE001 and S110 strict-rule budgets over their ceiling. Narrow to the one exception the %-format can actually raise and give it a real fallback instead of silently swallowing it. * refactor(logging): move color_message substitution into a helper The two record.color_message stores put LIT011 over its ceiling. Building the value in a pure helper leaves one store, marked rebind-ok since scrubbing a record in place is the logging.Filter contract. Also pins the ordering that makes the substitution safe: it has to run before args are cleared, which puts it before the extra-field loop that redacts the result, so a secret arriving through record.args is still scrubbed out of color_message. --- litellm/_logging.py | 24 ++++++++ tests/test_litellm/test_secret_redaction.py | 65 +++++++++++++++++++++ 2 files changed, 89 insertions(+) diff --git a/litellm/_logging.py b/litellm/_logging.py index e55c6bc40a8..36fd51206c2 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -88,6 +88,24 @@ def redact_secrets(value: str) -> str: return _redact_string(value) +def _substituted_color_message(record: logging.LogRecord) -> str | None: + """Render a record's ``color_message`` against its args, or None if absent. + + uvicorn's colorized formatter re-renders `color_message` against + record.args at emit time (see uvicorn.logging.ColourizedFormatter) instead + of using the already-formatted record.msg, so it has to be substituted + before args are cleared or it is later formatted with no args and prints + the raw "%s://%s:%d" placeholders instead of the URL. + """ + color_message: Final = record.__dict__.get("color_message") + if not isinstance(color_message, str) or not record.args: + return None + try: + return color_message % record.args + except TypeError: + return color_message + + class SecretRedactionFilter(logging.Filter): """Scrubs known secret/credential patterns from log records.""" @@ -97,6 +115,12 @@ class SecretRedactionFilter(logging.Filter): if not _ENABLE_SECRET_REDACTION: return True + # Runs before args are cleared, and before the extra-field loop below + # that redacts the substituted result. + substituted_color_message: Final = _substituted_color_message(record) + if substituted_color_message is not None: + record.color_message = substituted_color_message # rebind-ok: a Filter scrubs records in place + try: record.msg = _redact_string(record.getMessage()) record.args = None diff --git a/tests/test_litellm/test_secret_redaction.py b/tests/test_litellm/test_secret_redaction.py index 0188d87dfdb..7d50694c805 100644 --- a/tests/test_litellm/test_secret_redaction.py +++ b/tests/test_litellm/test_secret_redaction.py @@ -147,6 +147,71 @@ def test_filter_redacts_extra_fields(): assert record.region == "us-east-1" +def test_filter_preserves_uvicorn_color_message_args(): + """Regression test: uvicorn's startup banner logs a plain message plus a + colorized `extra={"color_message": ...}` copy of the same "%s://%s:%d" template, + both meant to be filled in from record.args. uvicorn's own ColourizedFormatter + re-substitutes color_message against record.args when writing to a TTY, instead + of using the already-formatted record.msg. + + Before this fix, the filter cleared record.args after substituting only + record.msg, so color_message was rendered with args=None and the raw + "%s://%s:%d" placeholders were printed instead of the real host/port. + """ + from uvicorn.logging import DefaultFormatter + + addr_format = "%s://%s:%d" + plain_message = f"Uvicorn running on {addr_format} (Press CTRL+C to quit)" + color_message = f"Uvicorn running on {addr_format} (Press CTRL+C to quit)" + + logger = logging.getLogger("uvicorn.error") + saved_handlers, saved_level = logger.handlers[:], logger.level + buf = StringIO() + handler = logging.StreamHandler(buf) + formatter = DefaultFormatter("%(levelprefix)s %(message)s") + formatter.use_colors = True + handler.setFormatter(formatter) + logger.handlers = [handler] + logger.setLevel(logging.INFO) + try: + logger.info( + plain_message, + "http", + "0.0.0.0", + 4000, + extra={"color_message": color_message}, + ) + output = buf.getvalue() + finally: + logger.handlers = saved_handlers + logger.setLevel(saved_level) + + assert "%s" not in output and "%d" not in output, f"unsubstituted placeholders leaked: {output!r}" + assert "http://0.0.0.0:4000" in output + + +def test_filter_redacts_secrets_substituted_into_color_message(): + """The color_message substitution runs before the extra-field redaction + loop, so a secret arriving through record.args lands in color_message and + must still be scrubbed. Substituting after that loop would ship the secret + to any colorized handler.""" + record = logging.LogRecord( + name="uvicorn.error", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="connecting with %s", + args=(SECRET,), + exc_info=None, + ) + record.color_message = "connecting with %s" + + _secret_filter.filter(record) + + assert SECRET not in record.color_message + assert "REDACTED" in record.color_message + + def test_disable_redaction_passes_secrets_through(): """When LITELLM_DISABLE_REDACT_SECRETS=true, secrets pass through.""" with patch("litellm._logging._ENABLE_SECRET_REDACTION", False):