fix(proxy): print startup messages once and without color codes off a terminal

This commit is contained in:
mateo-berri 2026-10-20 18:23:29 -07:00
parent 12650bb8d9
commit 0dd0ec6f2e
5 changed files with 141 additions and 30 deletions

View file

@ -598,6 +598,7 @@ _LOG_FORMAT_PREFIX: Final = "%(asctime)s - %(name)s:%(levelname)s"
_LOG_FORMAT_SUFFIX: Final = ": %(filename)s:%(lineno)s - %(message)s"
_PLAIN_LOG_FORMAT: Final = _LOG_FORMAT_PREFIX + _LOG_FORMAT_SUFFIX
_COLOR_LOG_FORMAT: Final = f"\033[92m{_LOG_FORMAT_PREFIX}\033[0m{_LOG_FORMAT_SUFFIX}"
_ANSI_ESCAPE: Final = re.compile(r"\x1b\[[0-9;]*m")
def _stream_is_tty(stream: TextIO | None) -> bool:
@ -612,15 +613,18 @@ def _stream_is_tty(stream: TextIO | None) -> bool:
return False
def _plain_log_format(stdout: TextIO | None, stderr: TextIO | None) -> str:
"""The plain-text log format, colorized only when both streams are an interactive terminal.
def _color_enabled(stream: TextIO | None) -> bool:
"""True when ANSI colors written to the stream reach an interactive terminal.
Honors the NO_COLOR convention from no-color.org: color is disabled when
NO_COLOR is present with a non-empty value.
"""
if os.environ.get("NO_COLOR"):
return _PLAIN_LOG_FORMAT
return _COLOR_LOG_FORMAT if _stream_is_tty(stdout) and _stream_is_tty(stderr) else _PLAIN_LOG_FORMAT
return not os.environ.get("NO_COLOR") and _stream_is_tty(stream)
def _plain_log_format(stdout: TextIO | None, stderr: TextIO | None) -> str:
"""The plain-text log format, colorized only when both streams are an interactive terminal."""
return _COLOR_LOG_FORMAT if _color_enabled(stdout) and _color_enabled(stderr) else _PLAIN_LOG_FORMAT
class LevelRoutingStreamHandler(logging.StreamHandler):
@ -744,7 +748,7 @@ class JsonFormatter(Formatter):
return dt.isoformat()
def format(self, record):
message_str: Final = record.getMessage()
message_str: Final = _ANSI_ESCAPE.sub("", record.getMessage())
json_record: Final[dict[str, object]] = {
"message": message_str,
"level": record.levelname,
@ -800,12 +804,14 @@ class CorrelationPlainFormatter(logging.Formatter):
"""Appends trace_id/session_id to plain-text log lines stamped by CorrelationContextFilter.
Mirrors JsonFormatter's handling of these two fields so request_correlation_in_logs
behaves the same whether or not json_logs is enabled.
behaves the same whether or not json_logs is enabled. Unless it was built with the color format,
it also drops the ANSI color codes a message carries, which a piped log would store as text.
"""
def format(self, record: logging.LogRecord) -> str:
rendered: Final = super().format(record)
formatted: Final = rendered if _is_redacted(record) else redact_string(rendered)
uncolored: Final = rendered if self._fmt == _COLOR_LOG_FORMAT else _ANSI_ESCAPE.sub("", rendered)
formatted: Final = uncolored if _is_redacted(record) else redact_string(uncolored)
trace_id: Final = getattr(record, "trace_id", None)
session_id: Final = getattr(record, "session_id", None)
if not trace_id and not session_id:
@ -899,23 +905,23 @@ verbose_proxy_logger.addFilter(_diagnostic_filter)
verbose_proxy_stdout_logger.addFilter(_diagnostic_filter)
verbose_logger.addFilter(_diagnostic_filter)
_ANSI_ESCAPE: Final = re.compile(r"\x1b\[[0-9;]*m")
def print_startup_message(message: str) -> None:
"""Write a boot-time message meant for the operator's terminal.
LITELLM_SUPPRESS_STARTUP_OUTPUT or litellm_settings.suppress_startup_output turns every one of them
off. Plain mode prints it unchanged, colors and spacing included, and flushes it so a piped stdout
shows it at once. With JSON logs on, every line of stdout is read by a log pipeline, so the message
goes out as one INFO record of the proxy logger instead, on stdout like the print whatever handlers
the logging config gave that logger, with the ANSI color codes and surrounding blank lines removed,
located at the caller and emitted at any log level; a blank spacer produces no record.
off. Plain mode prints it with its spacing, keeping the ANSI colors only when stdout is a color
terminal by the same check as the plain log format, so a container log never stores escape codes.
With JSON logs on, every line of stdout is read by a log pipeline, so the message goes out as one
INFO record of the proxy logger instead, on stdout like the print whatever handlers the logging
config gave that logger, with the ANSI color codes and surrounding blank lines removed, located at
the caller and emitted at any log level; a blank spacer produces no record.
"""
if litellm.suppress_startup_output is True:
return
if not litellm.json_logs:
print(message, flush=True) # noqa: T201 # plain mode: this is the operator-terminal print it replaces
printed: Final = message if _color_enabled(sys.stdout) else _ANSI_ESCAPE.sub("", message)
print(printed, flush=True) # noqa: T201 # plain mode: this is the operator-terminal print it replaces
return
text: Final = _ANSI_ESCAPE.sub("", message).strip("\n")
if not text:

View file

@ -6378,13 +6378,8 @@ class ProxyConfig:
search_tools_parsed: Final[list[SearchToolTypedDict]] = []
print_startup_message("\033[32mLiteLLM: Proxy initialized with Search Tools:\033[0m")
for search_tool in search_tools_raw:
# Display loaded search tool
search_tool_name = search_tool.get("search_tool_name", "")
search_provider = search_tool.get("litellm_params", {}).get("search_provider", "")
print_startup_message(f"\033[32m {search_tool_name} ({search_provider})\033[0m")
# Handle os.environ/ variables in litellm_params
litellm_params = search_tool.get("litellm_params", {})
@ -6560,7 +6555,7 @@ class ProxyConfig:
reset_color_code: Final = "\033[0m"
for key, value in litellm_settings.items():
if key == "cache" and value is True:
print_startup_message(f"{blue_color_code}\nSetting Cache on Proxy")
print_startup_message(f"\n{blue_color_code}Setting Cache on Proxy{reset_color_code}")
from litellm.caching.caching import Cache
cache_params = {}
@ -7230,6 +7225,19 @@ class ProxyConfig:
## SEARCH TOOLS SETTINGS
search_tools: Final[list[SearchToolTypedDict] | None] = self.parse_search_tools(config)
if search_tools:
print_startup_message(
"\n".join(
(
"\033[32mLiteLLM: Proxy initialized with Search Tools:\033[0m",
*(
f"\033[32m {tool.get('search_tool_name', '')} "
f"({tool.get('litellm_params', {}).get('search_provider', '')})\033[0m"
for tool in search_tools
),
)
)
)
## SANDBOX TOOLS SETTINGS
from litellm.sandbox.sandbox_tools import register_sandbox_tools

View file

@ -2,9 +2,10 @@
A container runtime reads the proxy's stdout through a pipe and keeps every line. This contract boots an owned
proxy with a search tool configured and a one-second config reload interval, serves a chat request, lets the
search tools reload job run several times and reads everything the proxy wrote. With
LITELLM_SUPPRESS_STARTUP_OUTPUT or litellm_settings.suppress_startup_output on, none of the startup messages
arrive, in plain and JSON mode alike.
search tools reload job run several times and reads everything the proxy wrote. With the setting off, every
startup message arrives, the search tools listing once per worker however many reloads ran, and no line
carries an ANSI color code, since the output is a pipe and not a terminal. With LITELLM_SUPPRESS_STARTUP_OUTPUT
or litellm_settings.suppress_startup_output on, none of them arrive, in plain and JSON mode alike.
"""
from __future__ import annotations
@ -34,6 +35,8 @@ STARTUP_MESSAGES: Final = (
SEARCH_TOOLS_HEADER,
"Postgres connection budget",
)
ANSI_ESCAPE: Final = "\x1b["
WORKER_COUNTS: Final = (1, 2)
CACHE_SETTINGS: Final[Mapping[str, JsonValue]] = {"cache": True, "cache_params": {"type": "redis"}}
@ -108,6 +111,20 @@ def _boot_reload_and_stop(
return log.read_text(), search_tool
@pytest.mark.parametrize("workers", WORKER_COUNTS)
def test_startup_messages_reach_a_piped_stdout_once_and_without_color_codes(
gateway: Gateway, tmp_path: Path, workers: int
) -> None:
log, search_tool = _boot_reload_and_stop(gateway, tmp_path, CACHE_SETTINGS, {}, workers)
for message in STARTUP_MESSAGES:
assert message in log, (message, log)
assert _lines_with(log, SEARCH_TOOLS_HEADER) == workers, log
assert _lines_with(log, f"{search_tool} (tavily)") == workers, log
colored: Final = tuple(line for line in log.splitlines() if ANSI_ESCAPE in line)
assert colored == (), "lines with ANSI color codes on a piped stdout:\n" + "\n".join(colored)
@pytest.mark.parametrize(
("litellm_settings", "overrides"),
[

View file

@ -2088,6 +2088,36 @@ def test_ProxyConfig_parse_search_tools_missing_returns_none():
assert pc.parse_search_tools({}) is None
@pytest.mark.asyncio
async def test_ProxyConfig_lists_search_tools_once_at_startup_not_on_every_reparse(
tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capfd: pytest.CaptureFixture[str]
):
"""The search tools reload job and add_deployment re-parse search_tools every config reload interval, so
the startup listing belongs to load_config alone, or a container log repeats it every 30 seconds."""
config_file: Final = tmp_path / "search.yaml"
config_file.write_text(
"model_list: []\n"
"search_tools:\n"
" - search_tool_name: web-search\n"
" litellm_params:\n"
" search_provider: tavily\n"
)
monkeypatch.setattr(litellm, "json_logs", False)
monkeypatch.setattr(litellm, "suppress_startup_output", False)
monkeypatch.setattr("litellm.proxy.proxy_server.prisma_client", None)
monkeypatch.setattr("litellm.proxy.proxy_server.store_model_in_db", False)
monkeypatch.delenv("LITELLM_CONFIG_BUCKET_NAME", raising=False)
proxy_config: Final = ProxyConfig()
await proxy_config.load_config(router=None, config_file_path=str(config_file))
for _ in range(3):
assert proxy_config.parse_search_tools(proxy_config.get_config_state()) is not None
out: Final = capfd.readouterr().out
assert out.count("Proxy initialized with Search Tools:") == 1, out
assert out.count("web-search (tavily)") == 1, out
def test_ProxyConfig_merge_config_and_db_search_tools_returns_superset():
config_tools = [
{

View file

@ -1408,6 +1408,32 @@ def test_plain_log_format_survives_hostile_streams(stdout, stderr):
assert _plain_log_format(stdout, stderr) == _PLAIN_LOG_FORMAT
def _router_success_record() -> logging.LogRecord:
return logging.LogRecord(
"LiteLLM Router", logging.INFO, "router.py", 1, "litellm.acompletion(model=%s)\033[32m 200 OK\033[0m", ("gpt-5.6",), None
)
@pytest.mark.parametrize(
("log_format", "want_suffix"),
[
(_COLOR_LOG_FORMAT, "litellm.acompletion(model=gpt-5.6)\033[32m 200 OK\033[0m"),
(_PLAIN_LOG_FORMAT, "router.py:1 - litellm.acompletion(model=gpt-5.6) 200 OK"),
],
)
def test_plain_formatter_keeps_message_colors_only_with_the_color_format(log_format: str, want_suffix: str):
"""A message that embeds color codes keeps them on a color terminal. Piped, or under NO_COLOR, the plain
format is chosen and the codes go too, so a container log never stores them as text."""
assert CorrelationPlainFormatter(log_format).format(_router_success_record()).endswith(want_suffix)
def test_json_formatter_drops_color_codes_from_the_message():
"""A JSON log line is read by a log pipeline, never a terminal, so a colored message arrives as plain text."""
assert json.loads(JsonFormatter().format(_router_success_record()))["message"] == (
"litellm.acompletion(model=gpt-5.6) 200 OK"
)
def test_level_routing_handler_falls_back_to_stderr_when_stdout_is_unusable(monkeypatch, capsys):
logger = logging.getLogger("test_level_routing_fallback")
logger.handlers.clear()
@ -1827,15 +1853,39 @@ def test_print_verbose_formats_args_only_when_set_verbose_is_on(monkeypatch, cap
assert capsys.readouterr().out == "key k1 value cached-vector\n"
def test_print_startup_message_prints_plain_mode_text_unchanged(monkeypatch, capfd):
"""Operators without JSON logs keep the colored, spaced terminal output exactly as before."""
class _CapturedStream(StringIO):
def __init__(self, tty: bool) -> None:
super().__init__()
self._tty = tty
def isatty(self) -> bool:
return self._tty
@pytest.mark.parametrize(
"stdout_tty, no_color, want_color",
[(True, None, True), (False, None, False), (True, "1", False)],
)
def test_print_startup_message_keeps_colors_only_on_a_color_terminal(
monkeypatch: pytest.MonkeyPatch, stdout_tty: bool, no_color: str | None, want_color: bool
):
"""Operators without JSON logs keep the colored, spaced output on a terminal. A container runtime reads
stdout through a pipe and stores the escape codes as text, so there, and under NO_COLOR, the colors go."""
monkeypatch.setattr(litellm, "json_logs", False)
if no_color is None:
monkeypatch.delenv("NO_COLOR", raising=False)
else:
monkeypatch.setenv("NO_COLOR", no_color)
stdout: Final = _CapturedStream(stdout_tty)
monkeypatch.setattr(sys, "stdout", stdout)
print_startup_message("\n\033[1;32mLiteLLM: Proxy initialized with Config, Set models:\033[0m\n")
out, err = capfd.readouterr()
assert out == "\n\033[1;32mLiteLLM: Proxy initialized with Config, Set models:\033[0m\n\n"
assert err == ""
assert stdout.getvalue() == (
"\n\033[1;32mLiteLLM: Proxy initialized with Config, Set models:\033[0m\n\n"
if want_color
else "\nLiteLLM: Proxy initialized with Config, Set models:\n\n"
)
@pytest.mark.parametrize("json_logs", [False, True])