fix(proxy): keep the JSON startup records on stdout under an operator handler on the proxy logger

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 in the window
where the banner, the feedback box and the cache notice are emitted: uvicorn applies it
after the CLI process switched JSON on and before initialize() re-installs the JSON
handler through load_config(). 41f92b745a sent the startup records through the proxy
logger's handlers and fell back to a JSON stdout handler only when there were none, so
under such a config the records landed in the operator's handler, as plaintext on stderr,
or vanished, where the prints they replace reached stdout whatever the logging config
said.

print_startup_message() now writes every startup record through the proxy's own JSON
handler on stdout, filters included, and never through the proxy logger's handlers; the
operator's handler gets nothing from a startup message, as it got nothing from the print.
The normal JSON handler is the same class, formatter and filters, so the records a
pipeline reads are unchanged when no operator config is in play.

Tests: tests/unit/test_logging.py gets the two handler shapes (red on f6f5957d16: the
record went to stderr as plaintext or nowhere); tests/integration/configuration/
test_json_logs_startup.py gets a silencing operator --log_config cell at 1 and 2 workers
(red on f6f5957d16: banner, feedback box and cache notice missing; green here).
This commit is contained in:
yucheng-berri 2026-10-19 17:25:36 -07:00
parent f6f5957d16
commit dabdecac95
3 changed files with 95 additions and 11 deletions

View file

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

View file

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

View file

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