mirror of
https://github.com/BerriAI/litellm.git
synced 2026-10-28 06:23:07 +00:00
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:
parent
e2303a3925
commit
41f92b745a
3 changed files with 88 additions and 4 deletions
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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."""
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue