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.
This commit is contained in:
yucheng-berri 2026-10-17 15:29:03 -07:00
parent e2303a3925
commit 41f92b745a
3 changed files with 88 additions and 4 deletions

View file

@ -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

View file

@ -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."""

View file

@ -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)