diff --git a/litellm/_logging.py b/litellm/_logging.py index 02704cf1a15..a4d91e2bc11 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -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: diff --git a/litellm/proxy/proxy_server.py b/litellm/proxy/proxy_server.py index 8476bc13fe9..df70b6f9f74 100644 --- a/litellm/proxy/proxy_server.py +++ b/litellm/proxy/proxy_server.py @@ -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 diff --git a/tests/integration/configuration/test_startup_output.py b/tests/integration/configuration/test_startup_output.py index d833dec525a..85278646fd2 100644 --- a/tests/integration/configuration/test_startup_output.py +++ b/tests/integration/configuration/test_startup_output.py @@ -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"), [ diff --git a/tests/unit/proxy/proxy_server/test_proxy_config.py b/tests/unit/proxy/proxy_server/test_proxy_config.py index e59dd19271c..b4857257eae 100644 --- a/tests/unit/proxy/proxy_server/test_proxy_config.py +++ b/tests/unit/proxy/proxy_server/test_proxy_config.py @@ -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 = [ { diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index aaedd17fe45..d1cd87d9c86 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -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])