From 41f92b745a71161487c4fa65ef55c6d1182eb531 Mon Sep 17 00:00:00 2001 From: yucheng-berri <293926326+yucheng-berri@users.noreply.github.com> Date: Sat, 17 Oct 2026 15:29:03 -0700 Subject: [PATCH] fix(proxy): keep the JSON banner when an operator --log_config names the proxy logger uvicorn applies --log_config after proxy_cli has switched JSON logging on and before initialize() switches it on again through load_config(). A logging config that names "LiteLLM Proxy" removes that logger's handlers in the window between the two, which is where initialize() emits the banner and the feedback box, so at one worker both went nowhere; two-worker children import litellm after uvicorn's logging setup and were not affected. print_startup_message() now falls back to a one-off JSON handler, on the stream the JSON handler uses, when the proxy logger has no handler of its own. Live, json_logs on plus a log_config naming the proxy logger, one worker: main prints the banner and the feedback box as plaintext, e2303a3925 prints neither, this head prints both as one JSON record each. New unit test fails on e2303a3925; new integration cell test_json_logs_with_operator_log_config_keeps_every_line_json passes at one and two workers. --- litellm/_logging.py | 14 +++++- .../configuration/test_json_logs_startup.py | 48 +++++++++++++++++-- tests/unit/test_logging.py | 30 ++++++++++++ 3 files changed, 88 insertions(+), 4 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index 720d0b99585..72a79412749 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -932,10 +932,22 @@ def print_startup_message(message: str) -> None: # handler (LITELLM_LOG), and still runs the logger's and the handler's filters and the formatter. if not verbose_proxy_logger.filter(record): return - for json_handler in verbose_proxy_logger.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(); 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) +def _fallback_json_handler() -> logging.Handler: + """JSON handler for a startup message that arrives while the proxy logger has no handler of its own.""" + handler: Final = LevelRoutingStreamHandler() + handler.setFormatter(JsonFormatter()) + handler.addFilter(_secret_filter) + handler.addFilter(_correlation_filter) + return handler + + def _suppress_loggers(): """Suppress noisy loggers at INFO level""" # Suppress httpx request logging at INFO level diff --git a/tests/integration/configuration/test_json_logs_startup.py b/tests/integration/configuration/test_json_logs_startup.py index 59cfdd6128b..bfc4f20f9bd 100644 --- a/tests/integration/configuration/test_json_logs_startup.py +++ b/tests/integration/configuration/test_json_logs_startup.py @@ -44,6 +44,16 @@ WORKER_COUNTS: Final = (1, 2) UNKNOWN_MODEL_STATUS: Final = 400 BURST_SIZE: Final = 16 CACHE_SETTINGS: Final[Mapping[str, JsonValue]] = {"cache": True, "cache_params": {"type": "redis"}} +# an operator logging config of the usual shape: it sets the proxy logger's level and gives it no handler +# of its own, and formats everything else, uvicorn included, as JSON through the root handler +OPERATOR_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"}}, + "loggers": {"LiteLLM Proxy": {"level": "INFO"}}, + "root": {"level": "INFO", "handlers": ["stdout"]}, +} def _models() -> tuple[str, str]: @@ -112,8 +122,17 @@ def _boot_serve_and_stop( overrides: Mapping[str, str], workers: int, models: tuple[str, ...], + extra_arguments: tuple[str, ...] = (), ) -> str: - with owned_proxy_process(gateway, directory, overrides, config=config, workers=workers, database_setup=()) as owned: + with owned_proxy_process( + gateway, + directory, + overrides, + config=config, + workers=workers, + database_setup=(), + extra_arguments=extra_arguments, + ) as owned: _serve(owned.gateway, models) log: Final = owned.log return log.read_text() @@ -133,7 +152,9 @@ def _serve(gateway: Gateway, models: tuple[str, ...]) -> None: assert rejected.status_code == UNKNOWN_MODEL_STATUS, rejected.text -def _assert_every_line_is_json(log: str, workers: int, models: tuple[str, ...]) -> None: +def _assert_every_line_is_json( + log: str, workers: int, models: tuple[str, ...], *, redis_auth_cache_line: bool = True +) -> None: plaintext: Final = _non_json_lines(log) assert plaintext == (), "plaintext lines with JSON logs on:\n" + "\n".join(plaintext) messages: Final = _messages(log) @@ -142,7 +163,8 @@ def _assert_every_line_is_json(log: str, workers: int, models: tuple[str, ...]) for model in models: assert any(model in message for message in messages), (model, messages) assert any(CACHE_LINE in message for message in messages), messages - assert any(REDIS_AUTH_CACHE_LINE in message for message in messages), messages + if redis_auth_cache_line: + assert any(REDIS_AUTH_CACHE_LINE in message for message in messages), messages assert any(CONNECTION_BUDGET_LINE in message for message in messages), messages assert sum(BANNER_FRAGMENT in message for message in messages) == workers, messages assert sum(FEEDBACK_BOX_LINE in message for message in messages) == workers, messages @@ -168,6 +190,26 @@ def test_json_logs_config_keeps_every_line_json(gateway: Gateway, tmp_path: Path _assert_every_line_is_json(log, workers, models) +@pytest.mark.parametrize("workers", WORKER_COUNTS) +def test_json_logs_with_operator_log_config_keeps_every_line_json( + gateway: Gateway, tmp_path: Path, workers: int +) -> None: + """uvicorn applies an operator `--log_config` after the CLI process switched JSON on and before + `initialize()` switches it on again through the config; a config that names the proxy logger leaves it + without handlers in that window, where the banner and the feedback box are emitted. They still arrive, + as JSON, one per worker, and the operator's own formatter keeps uvicorn's lines JSON. The Redis + auth-cache line is a regular logger line written in that same window; this log_config removed the + proxy logger's handlers and left propagation off, so it is lost at one worker 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_log_config.yaml" + log_config.write_text(yaml.safe_dump(dict(OPERATOR_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_default_level_keeps_every_line_json(gateway: Gateway, tmp_path: Path) -> None: """Without LITELLM_LOG the proxy loggers sit at WARNING; the startup notices a plain-mode operator always sees still arrive, as JSON, and nothing arrives as plaintext.""" diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index fb4189100ee..2c969a1059f 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -1866,6 +1866,36 @@ def test_print_startup_message_shows_above_the_json_handler_level(monkeypatch, c assert [json.loads(raw)["message"] for raw in lines] == ["Setting Cache on Proxy"] +def test_print_startup_message_emits_json_after_an_operator_log_config_removed_the_handlers( + request, monkeypatch, capfd +): + """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, and they + still go out as one JSON record each, on stdout.""" + 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, "loggers": {"LiteLLM Proxy": {"level": "INFO"}}} + ) + assert verbose_proxy_logger.handlers == [] + + print_startup_message("\n\033[1;37m# Give Feedback / Get Help #\033[0m\n") + + out, err = capfd.readouterr() + assert 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_blank_spacer_emits_no_json_record(monkeypatch, capfd): """A spacer that only pads the terminal has nothing to say to a log pipeline.""" monkeypatch.setattr(litellm, "json_logs", True)