mirror of
https://github.com/BerriAI/litellm.git
synced 2026-10-27 06:13:07 +00:00
fix(proxy): keep a long startup listing whole in its JSON record
print_startup_message ran its record through the proxy logger's filters, so
in JSON mode the required-migration SQL list and the policy list were
middle-truncated at MAX_STRING_LENGTH_STDOUT_LOG (4096 by default) with the
litellm_truncated marker, where the prints they replace showed them whole.
That cap bounds echoed request payloads; a startup message is operator text,
so the record now gets the uncapped processing of a DEBUG line: secret
redaction and base64 collapse still apply, the text cap does not.
Red on 41f92b745a, green here:
- tests/unit/test_logging.py: a listing longer than the cap comes out whole;
a credential in a startup message is still redacted
- tests/integration/configuration/test_json_logs_startup.py: a 60-policy
config boots with json_logs on and the policy listing record (9762 chars)
carries every policy with no truncation marker (4096 chars, marker, on
the unfixed tree)
This commit is contained in:
parent
41f92b745a
commit
2d7a2d6844
3 changed files with 99 additions and 4 deletions
|
|
@ -929,8 +929,16 @@ def print_startup_message(message: str) -> None:
|
||||||
)
|
)
|
||||||
# The print this replaces shows at any log level, so the record skips the level checks of the
|
# The print this replaces shows at any log level, so the record skips the level checks of the
|
||||||
# proxy logger (at the root's WARNING in the CLI process until initialize() runs) and of its JSON
|
# proxy logger (at the root's WARNING in the CLI process until initialize() runs) and of its JSON
|
||||||
# handler (LITELLM_LOG), and still runs the logger's and the handler's filters and the formatter.
|
# handler (LITELLM_LOG). It also skips the logger's stdout cap: that cap bounds echoed request
|
||||||
if not verbose_proxy_logger.filter(record):
|
# payloads, while a startup message is operator text the print showed whole (the required migration
|
||||||
|
# SQL, the policy list), so it gets the uncapped processing of a DEBUG line, secret redaction and
|
||||||
|
# base64 collapse included, before the handler's filters and the formatter.
|
||||||
|
if not _process_record(
|
||||||
|
record,
|
||||||
|
base64_limit=_get_max_base64_length_stdout_log(),
|
||||||
|
text_limit=0,
|
||||||
|
redact=_ENABLE_SECRET_REDACTION,
|
||||||
|
):
|
||||||
return
|
return
|
||||||
# uvicorn applies an operator --log_config after proxy_cli's turn_on_json() and before initialize()
|
# 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
|
# re-installs the JSON handler through load_config(); a config that names "LiteLLM Proxy" leaves the
|
||||||
|
|
|
||||||
|
|
@ -6,7 +6,8 @@ serves a chat request on every configured model plus one rejected request, stops
|
||||||
rejects any line of its output that is not one JSON record, while checking that the
|
rejects any line of its output that is not one JSON record, while checking that the
|
||||||
startup information those lines used to carry is still present as JSON records. JSON mode is switched
|
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
|
on through the environment and through the config, at one and two uvicorn workers, at the INFO, the
|
||||||
default and the WARNING log level, and under a concurrent burst that lands on both workers.
|
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.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
from __future__ import annotations
|
from __future__ import annotations
|
||||||
|
|
@ -44,6 +45,12 @@ WORKER_COUNTS: Final = (1, 2)
|
||||||
UNKNOWN_MODEL_STATUS: Final = 400
|
UNKNOWN_MODEL_STATUS: Final = 400
|
||||||
BURST_SIZE: Final = 16
|
BURST_SIZE: Final = 16
|
||||||
CACHE_SETTINGS: Final[Mapping[str, JsonValue]] = {"cache": True, "cache_params": {"type": "redis"}}
|
CACHE_SETTINGS: Final[Mapping[str, JsonValue]] = {"cache": True, "cache_params": {"type": "redis"}}
|
||||||
|
# the policy list and the required migration SQL are the startup listings that outgrow the stdout cap
|
||||||
|
# (MAX_STRING_LENGTH_STDOUT_LOG, 4096 by default) that bounds echoed request payloads
|
||||||
|
STDOUT_CAP: Final = 4096
|
||||||
|
POLICY_COUNT: Final = 60
|
||||||
|
POLICY_LIST_HEADER: Final = "LiteLLM Policy Engine: Loaded"
|
||||||
|
TRUNCATION_MARKER: Final = "litellm_truncated"
|
||||||
# an operator logging config of the usual shape: it sets the proxy logger's level and gives it no handler
|
# 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
|
# of its own, and formats everything else, uvicorn included, as JSON through the root handler
|
||||||
OPERATOR_LOG_CONFIG: Final[Mapping[str, JsonValue]] = {
|
OPERATOR_LOG_CONFIG: Final[Mapping[str, JsonValue]] = {
|
||||||
|
|
@ -61,8 +68,22 @@ def _models() -> tuple[str, str]:
|
||||||
return (f"json-logs-first-{stamp}", f"json-logs-second-{stamp}")
|
return (f"json-logs-first-{stamp}", f"json-logs-second-{stamp}")
|
||||||
|
|
||||||
|
|
||||||
|
def _policies() -> dict[str, JsonValue]:
|
||||||
|
stamp: Final = uuid.uuid4().hex
|
||||||
|
return {
|
||||||
|
f"startup-listing-policy-{n:02d}-{stamp}": {
|
||||||
|
"description": f"policy {n:02d} of a listing that runs past the stdout cap meant for request payloads"
|
||||||
|
}
|
||||||
|
for n in range(POLICY_COUNT)
|
||||||
|
}
|
||||||
|
|
||||||
|
|
||||||
def _write_config(
|
def _write_config(
|
||||||
directory: Path, upstream_url: str, models: tuple[str, ...], litellm_settings: Mapping[str, JsonValue]
|
directory: Path,
|
||||||
|
upstream_url: str,
|
||||||
|
models: tuple[str, ...],
|
||||||
|
litellm_settings: Mapping[str, JsonValue],
|
||||||
|
extra_sections: Mapping[str, JsonValue] | None = None,
|
||||||
) -> Path:
|
) -> Path:
|
||||||
config: Final = directory / f"json_logs_{uuid.uuid4().hex}.yaml"
|
config: Final = directory / f"json_logs_{uuid.uuid4().hex}.yaml"
|
||||||
config.write_text(
|
config.write_text(
|
||||||
|
|
@ -85,6 +106,7 @@ def _write_config(
|
||||||
"database_url": "os.environ/DATABASE_URL",
|
"database_url": "os.environ/DATABASE_URL",
|
||||||
"disable_prisma_schema_update": True,
|
"disable_prisma_schema_update": True,
|
||||||
},
|
},
|
||||||
|
**(extra_sections or {}),
|
||||||
},
|
},
|
||||||
sort_keys=False,
|
sort_keys=False,
|
||||||
)
|
)
|
||||||
|
|
@ -210,6 +232,28 @@ 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)
|
_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):
|
||||||
|
the print it replaces showed it whole, and the stdout cap exists for echoed request payloads, so the JSON
|
||||||
|
record must not be middle-truncated."""
|
||||||
|
models: Final = _models()
|
||||||
|
policies: Final = _policies()
|
||||||
|
config: Final = _write_config(
|
||||||
|
tmp_path, gateway.upstream_url, models, {**CACHE_SETTINGS, "json_logs": True}, {"policies": policies}
|
||||||
|
)
|
||||||
|
|
||||||
|
log: Final = _boot_serve_and_stop(gateway, tmp_path, config, {"LITELLM_LOG": "INFO"}, 1, models)
|
||||||
|
|
||||||
|
_assert_every_line_is_json(log, 1, models)
|
||||||
|
listings: Final = tuple(message for message in _messages(log) if POLICY_LIST_HEADER in message)
|
||||||
|
assert len(listings) == 1, listings
|
||||||
|
assert len(listings[0]) > STDOUT_CAP, len(listings[0])
|
||||||
|
assert TRUNCATION_MARKER not in listings[0], listings[0]
|
||||||
|
for policy in policies:
|
||||||
|
assert policy in listings[0], (policy, listings[0])
|
||||||
|
|
||||||
|
|
||||||
def test_json_logs_default_level_keeps_every_line_json(gateway: Gateway, tmp_path: Path) -> None:
|
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
|
"""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."""
|
always sees still arrive, as JSON, and nothing arrives as plaintext."""
|
||||||
|
|
|
||||||
|
|
@ -1896,6 +1896,49 @@ def test_print_startup_message_emits_json_after_an_operator_log_config_removed_t
|
||||||
assert record["component"] == "LiteLLM Proxy"
|
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,
|
||||||
|
so the JSON record carries the whole listing too."""
|
||||||
|
monkeypatch.setenv("MAX_STRING_LENGTH_STDOUT_LOG", "500")
|
||||||
|
monkeypatch.setattr(litellm, "json_logs", True)
|
||||||
|
monkeypatch.setattr(sys, "excepthook", sys.excepthook) # turn_on_json swaps it; put it back at teardown
|
||||||
|
turn_on_json()
|
||||||
|
commands: Final = tuple(f'ALTER TABLE "LiteLLM_Table{n}" ADD COLUMN "column_{n}" TEXT;' for n in range(40))
|
||||||
|
listing: Final = "\n".join(("Changes to DB Schema detected", "Required SQL commands:", *commands))
|
||||||
|
assert len(listing) > 500
|
||||||
|
|
||||||
|
print_startup_message(listing)
|
||||||
|
|
||||||
|
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 LITELLM_TRUNCATED_PAYLOAD_FIELD not in record["message"]
|
||||||
|
assert record["message"] == listing
|
||||||
|
|
||||||
|
|
||||||
|
def test_print_startup_message_still_redacts_a_secret_in_the_uncapped_record(monkeypatch, capfd):
|
||||||
|
"""Skipping the stdout cap must not skip secret redaction: a startup message that echoes a credential,
|
||||||
|
such as a failed migration diff quoting the database error, goes out scrubbed."""
|
||||||
|
monkeypatch.setattr(litellm, "json_logs", True)
|
||||||
|
monkeypatch.setattr(sys, "excepthook", sys.excepthook) # turn_on_json swaps it; put it back at teardown
|
||||||
|
turn_on_json()
|
||||||
|
|
||||||
|
print_startup_message(
|
||||||
|
'Failed to generate migration diff. Error: {"api_key": "sk-abcdefghijklmnopqrstuvwxyz0123456789"}'
|
||||||
|
)
|
||||||
|
|
||||||
|
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 "sk-abcdefghijklmnopqrstuvwxyz0123456789" not in lines[0]
|
||||||
|
assert record["message"] == 'Failed to generate migration diff. Error: {"REDACTED"}'
|
||||||
|
|
||||||
|
|
||||||
def test_print_startup_message_blank_spacer_emits_no_json_record(monkeypatch, capfd):
|
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."""
|
"""A spacer that only pads the terminal has nothing to say to a log pipeline."""
|
||||||
monkeypatch.setattr(litellm, "json_logs", True)
|
monkeypatch.setattr(litellm, "json_logs", True)
|
||||||
|
|
|
||||||
Loading…
Add table
Reference in a new issue