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