diff --git a/litellm/_logging.py b/litellm/_logging.py index 72a79412749..647a62f4102 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -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 # 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. - if not verbose_proxy_logger.filter(record): + # handler (LITELLM_LOG). It also skips the logger's stdout cap: that cap bounds echoed request + # 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 # 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 diff --git a/tests/integration/configuration/test_json_logs_startup.py b/tests/integration/configuration/test_json_logs_startup.py index bfc4f20f9bd..8156eb7dc87 100644 --- a/tests/integration/configuration/test_json_logs_startup.py +++ b/tests/integration/configuration/test_json_logs_startup.py @@ -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 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, 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 @@ -44,6 +45,12 @@ 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"}} +# 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 # of its own, and formats everything else, uvicorn included, as JSON through the root handler 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}") +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( - 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: config: Final = directory / f"json_logs_{uuid.uuid4().hex}.yaml" config.write_text( @@ -85,6 +106,7 @@ def _write_config( "database_url": "os.environ/DATABASE_URL", "disable_prisma_schema_update": True, }, + **(extra_sections or {}), }, 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) +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: """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.""" diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 2c969a1059f..df90ac0f3ce 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -1896,6 +1896,49 @@ def test_print_startup_message_emits_json_after_an_operator_log_config_removed_t 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): """A spacer that only pads the terminal has nothing to say to a log pipeline.""" monkeypatch.setattr(litellm, "json_logs", True)