diff --git a/litellm/_logging.py b/litellm/_logging.py index 647a62f4102..034f0f7785b 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -905,9 +905,10 @@ def print_startup_message(message: str) -> None: """Write a boot-time message meant for the operator's terminal. Plain mode prints it unchanged, colors and spacing included. With JSON logs on, every line of - stdout is read by a log pipeline, so the message goes out as one INFO record on the proxy logger - instead, on stdout like the print, 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. + 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 not litellm.json_logs: print(message) # noqa: T201 # plain mode: this is the operator-terminal print it replaces @@ -940,15 +941,16 @@ def print_startup_message(message: str) -> None: redact=_ENABLE_SECRET_REDACTION, ): return - # uvicorn applies an operator --log_config after proxy_cli's turn_on_json() and before initialize() - # re-installs the JSON handler through load_config(); a config that names "LiteLLM Proxy" leaves the - # logger without handlers in that window, where the banner and the feedback box are emitted. - for json_handler in verbose_proxy_logger.handlers or (_fallback_json_handler(),): - json_handler.handle(record) + # The print wrote to stdout whatever the logging config said, so the record goes through the proxy's + # own JSON handler on stdout rather than the proxy logger's handlers: uvicorn applies an operator + # --log_config after proxy_cli's turn_on_json() and before initialize() re-installs the JSON handler + # through load_config(), and in that window, where the banner and the feedback box are emitted, a + # config that names "LiteLLM Proxy" has left the logger with no handler or with the operator's own. + _startup_json_handler().handle(record) -def _fallback_json_handler() -> logging.Handler: - """JSON handler for a startup message that arrives while the proxy logger has no handler of its own.""" +def _startup_json_handler() -> logging.Handler: + """The proxy's JSON handler on stdout, filters included, for one startup message.""" handler: Final = LevelRoutingStreamHandler() handler.setFormatter(JsonFormatter()) handler.addFilter(_secret_filter) diff --git a/tests/integration/configuration/test_json_logs_startup.py b/tests/integration/configuration/test_json_logs_startup.py index 8156eb7dc87..cb180b8ec6e 100644 --- a/tests/integration/configuration/test_json_logs_startup.py +++ b/tests/integration/configuration/test_json_logs_startup.py @@ -7,7 +7,8 @@ rejects any line of its output that is not one JSON record, while checking that startup information those lines used to carry is still present as JSON records. JSON mode is switched on through the environment and through the config, at one and two uvicorn workers, at the INFO, the default and the WARNING log level, under a concurrent burst that lands on both workers, under an operator ---log_config that names the proxy logger, and with a policy list longer than the stdout cap. +--log_config that names the proxy logger or gives it a handler of its own, and with a policy list longer +than the stdout cap. """ from __future__ import annotations @@ -61,6 +62,18 @@ OPERATOR_LOG_CONFIG: Final[Mapping[str, JsonValue]] = { "loggers": {"LiteLLM Proxy": {"level": "INFO"}}, "root": {"level": "INFO", "handlers": ["stdout"]}, } +# an operator logging config that silences the proxy logger with a handler of its own and keeps the rest JSON +OPERATOR_SILENCING_LOG_CONFIG: Final[Mapping[str, JsonValue]] = { + "version": 1, + "disable_existing_loggers": False, + "formatters": {"json": {"()": "litellm._logging.JsonFormatter"}}, + "handlers": { + "stdout": {"class": "logging.StreamHandler", "stream": "ext://sys.stdout", "formatter": "json"}, + "silence": {"class": "logging.NullHandler"}, + }, + "loggers": {"LiteLLM Proxy": {"level": "INFO", "handlers": ["silence"], "propagate": False}}, + "root": {"level": "INFO", "handlers": ["stdout"]}, +} def _models() -> tuple[str, str]: @@ -232,6 +245,25 @@ def test_json_logs_with_operator_log_config_keeps_every_line_json( _assert_every_line_is_json(log, workers, models, redis_auth_cache_line=False) +@pytest.mark.parametrize("workers", WORKER_COUNTS) +def test_json_logs_with_operator_handler_on_the_proxy_logger_keeps_the_startup_notices( + gateway: Gateway, tmp_path: Path, workers: int +) -> None: + """An operator `--log_config` that gives the proxy logger a handler of its own, here a NullHandler that + silences it, is in force in the window where the banner and the feedback box are emitted. The prints + they replace wrote to stdout whatever the logging config said, so both still arrive there as JSON, one + per worker. The Redis auth-cache line is a regular logger line written in that same window and goes + to the operator's handler, so it is silenced on main and here alike.""" + models: Final = _models() + config: Final = _write_config(tmp_path, gateway.upstream_url, models, {**CACHE_SETTINGS, "json_logs": True}) + log_config: Final = tmp_path / "operator_silencing_log_config.yaml" + log_config.write_text(yaml.safe_dump(dict(OPERATOR_SILENCING_LOG_CONFIG))) + log: Final = _boot_serve_and_stop( + gateway, tmp_path, config, {"LITELLM_LOG": "INFO"}, workers, models, ("--log_config", str(log_config)) + ) + _assert_every_line_is_json(log, workers, models, redis_auth_cache_line=False) + + def test_json_logs_keeps_a_startup_listing_longer_than_the_stdout_cap_whole(gateway: Gateway, tmp_path: Path) -> None: """A startup listing longer than MAX_STRING_LENGTH_STDOUT_LOG reaches the pipeline whole. The policy list stands in for every such listing (the required migration SQL on a drifted database is the other one): diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index df90ac0f3ce..367fb24dfa4 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -1896,6 +1896,56 @@ def test_print_startup_message_emits_json_after_an_operator_log_config_removed_t assert record["component"] == "LiteLLM Proxy" +OPERATOR_HANDLERS_ON_THE_PROXY_LOGGER: Final = { + "silenced": {"class": "logging.NullHandler"}, + "stderr_warning": { + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + "level": "WARNING", + "formatter": "plain", + }, +} + + +@pytest.mark.parametrize("handler", sorted(OPERATOR_HANDLERS_ON_THE_PROXY_LOGGER)) +def test_print_startup_message_stays_on_stdout_under_an_operator_handler_on_the_proxy_logger( + request, monkeypatch, capfd, handler: str +): + """An operator `--log_config` that gives "LiteLLM Proxy" a handler of its own, a NullHandler that silences + it or a plain WARNING-level handler on stderr, is in force when the banner and the feedback box are + emitted; the print they replace wrote to stdout whatever the logging config said, so the record still + goes out as one JSON record on stdout and the operator's handler gets nothing.""" + import logging.config + + monkeypatch.setattr(litellm, "json_logs", True) + monkeypatch.setattr(sys, "excepthook", sys.excepthook) + turn_on_json() + request.addfinalizer(turn_on_json) # put the JSON handler back for the tests that follow + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, + "formatters": {"plain": {"format": "%(levelname)s %(message)s"}}, + "handlers": {"proxy": OPERATOR_HANDLERS_ON_THE_PROXY_LOGGER[handler]}, + "loggers": {"LiteLLM Proxy": {"level": "INFO", "handlers": ["proxy"], "propagate": False}}, + } + ) + assert len(verbose_proxy_logger.handlers) == 1 and not isinstance( + verbose_proxy_logger.handlers[0], LevelRoutingStreamHandler + ) + + print_startup_message("\n\033[1;37m# Give Feedback / Get Help #\033[0m\n") + + out, err = capfd.readouterr() + assert err == "", err + lines: Final = [raw for raw in out.splitlines() if raw.strip()] + assert len(lines) == 1, lines + record: Final = json.loads(lines[0]) + assert record["message"] == "# Give Feedback / Get Help #" + assert record["level"] == "INFO" + assert record["component"] == "LiteLLM Proxy" + + def test_print_startup_message_keeps_a_listing_longer_than_the_stdout_cap_whole(monkeypatch, capfd): """The required migration SQL and the policy list run past MAX_STRING_LENGTH_STDOUT_LOG on a drifted deployment. The prints they replace showed them whole, and that cap exists for echoed request payloads,