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)