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:
yucheng-berri 2026-10-17 16:50:21 -07:00
parent 41f92b745a
commit 2d7a2d6844
3 changed files with 99 additions and 4 deletions

View file

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

View file

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

View file

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