mirror of
https://github.com/BerriAI/litellm.git
synced 2026-10-30 06:43:27 +00:00
* fix(proxy): keep every startup line JSON when json_logs is on Boot-time messages the proxy printed straight to stdout (banner, feedback box, model list, cache and callback notices, policy table, migration notices, CLI launch notes) and the first records of uvicorn- or granian-spawned workers came out as plain text while json_logs was on, breaking log pipelines that parse every line as JSON. - print_startup_message() prints unchanged in plain mode and, with json_logs on, emits one INFO record on the proxy logger (ANSI stripped) that skips the logger and handler level checks like the print it replaces; show_banner() routes to it in JSON mode only - the CLI exports JSON_LOGS=true when the config sets json_logs so spawned workers log JSON from their first record - the --enforce_prisma_migration_check deprecation notice prints after the config is read so a config-only json_logs covers it Resolves LIT-1624 * fix(proxy): keep show_banner() SDK-free, pick the JSON banner in initialize() Since #46803 the `lite` shell calls show_banner() against an uninitialized litellm package, and reading litellm.json_logs inside it initialized the whole SDK at the banner (0.14 s to 0.83 s for a bare `lite` here, the seconds that PR removed on small VMs). show_banner() is back to its main version; the proxy's initialize() now emits the JSON banner record itself and calls show_banner() only in plain mode. The banner unit tests move to the initialize() call site. * 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,e2303a3925prints 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. * 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 on41f92b745a, 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) * fix(proxy): keep the --enforce_prisma_migration_check notice on --health and --test This PR moved the deprecation notice after the config is read, so that a json_logs set only in the config applies to it; --health and --test return before that point and stopped printing it, a visible change main did not have. The notice is now also emitted before those two returns, through the same helper, so a deployment running `litellm --health --enforce_prisma_migration_check` still learns the flag is dead, as on main. A normal server start emits it once, after the config, as in the previous commit. Red on2d7a2d6844, green here: tests/unit/proxy/test_proxy_cli.py asserts the notice on --health and on --test. * 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().41f92b745asent 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 onf6f5957d16: 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 onf6f5957d16: banner, feedback box and cache notice missing; green here). * fix(proxy): print the --enforce_prisma_migration_check notice when the config fails to loadf6f5957d16printed the deprecation notice after the config is read, so a json_logs set only in the config makes it a JSON record. A boot whose config file is missing or does not parse then exited before that point and never printed it, where main printed it before the error (10-20 gauntlet finding). The notice is printed where main printed it, unless a config file can still switch json_logs on: then it is held until the config is read and printed right after the json_logs switch, and a click close callback prints it on the way out if the boot fails first. functools.cache keeps it to one print either way. Tests: tests/unit/proxy/test_proxy_cli.py covers a failed config read (red on75043aed83), a plain config printing it once and a config-only json_logs making it one JSON record; tests/integration/configuration/test_json_logs_startup.py adds the JSON cell and a missing and an unparseable config cell (red on75043aed83, green here), through refused_boot_log, which now takes extra CLI arguments. * fix(proxy): keep startup records as printed instead of running secret redaction In JSON mode the startup messages ran secret redaction, which the prints they replace never had. Its sk- key pattern has no left boundary, so a model named risk-assessment-gpt4o was logged as riREDACTED in the model list (10-21 gauntlet finding). The records now skip redaction like the prints did; the processed record still counts as scrubbed, so the handler's secret filter and the formatter leave it alone. The stdout cap stays off and base64 collapse stays on, as before. Tests: tests/unit/test_logging.py checks the model name comes out whole (red on7d17f126e5), replacing the test that asserted startup records were redacted; tests/integration/configuration/test_json_logs_startup.py adds a boot with a risk-assessment-<id> model whose model list record carries the name (red on7d17f126e5). * refactor(proxy): meet the AGENTS.md rules Greptile flagged on the startup-message change The policy listing builds its rows as tuples in two helpers instead of appending to a list; plain output is unchanged (same bytes as before across 3000 random policy and attachment configs). The explanatory comments added with this change are gone, and the docstring of print_startup_message now says the record is whole and unredacted. Tests: the migration-diff JSON test no longer runs the fake prisma CLI; it checks the skipped-diff notice in-process, and the fixture extension it needed is reverted. The json_logs export and deprecation-notice CLI tests run the real proxy module and a real config file instead of a mocked ProxyConfig and proxy module, and the --health/--test notice tests no longer patch our helpers. Each still fails when the export, the hold or call_on_close is removed. New test parameters are typed. --------- Co-authored-by: yucheng-berri <293926326+yucheng-berri@users.noreply.github.com>
107 lines
4.2 KiB
Python
107 lines
4.2 KiB
Python
import json
|
|
import logging
|
|
import sys
|
|
from typing import Final
|
|
|
|
import pytest
|
|
|
|
import litellm
|
|
from litellm._logging import turn_on_json, verbose_logger, verbose_proxy_logger
|
|
|
|
|
|
def test_check_migration_out_of_sync(mocker):
|
|
"""
|
|
Test that the check_prisma_schema_diff function
|
|
- 🚨 [IMPORTANT] Does NOT Raise an Exception when the Prisma schema is out of sync with the database.
|
|
- logs an error when the Prisma schema is out of sync with the database.
|
|
"""
|
|
# Import the module first so check_migration is in sys.modules,
|
|
# then patch the logger reference in that module directly (not the source
|
|
# module) so the patch works regardless of import order or xdist worker
|
|
# assignment.
|
|
from litellm.proxy.db import check_migration
|
|
|
|
# Mock the helper function to simulate out-of-sync state
|
|
mock_logger = mocker.patch.object(
|
|
check_migration,
|
|
"verbose_logger",
|
|
autospec=True,
|
|
)
|
|
mocker.patch.object(
|
|
check_migration,
|
|
"check_prisma_schema_diff_helper",
|
|
return_value=(True, ["ALTER TABLE users ADD COLUMN new_field TEXT;"]),
|
|
)
|
|
|
|
# Run the function - it should not raise an error
|
|
try:
|
|
check_migration.check_prisma_schema_diff(db_url="mock_url")
|
|
except Exception as e:
|
|
pytest.fail(f"check_prisma_schema_diff raised an unexpected exception: {e}")
|
|
|
|
# Verify the logger was called with the expected message
|
|
check_migration.verbose_logger.exception.assert_called_once()
|
|
actual_message = check_migration.verbose_logger.exception.call_args[0][0]
|
|
assert "prisma schema out of sync with db" in actual_message
|
|
|
|
|
|
@pytest.mark.timeout(30)
|
|
def test_migrate_diff_stops_at_its_budget_and_takes_its_process_tree_with_it(fake_prisma_cli, monkeypatch):
|
|
"""
|
|
`prisma migrate diff` ran unbounded, so a database that never answers hung boot
|
|
before uvicorn ever started, and interrupting the proxy orphaned the schema engine.
|
|
"""
|
|
from litellm.proxy.db.check_migration import check_prisma_schema_diff_helper
|
|
|
|
monkeypatch.setenv("FAKE_PRISMA_HANG_FIRST", "1")
|
|
|
|
assert check_prisma_schema_diff_helper("postgresql://u:p@localhost:9/x") == (False, [])
|
|
assert fake_prisma_cli.calls == [
|
|
["migrate", "diff", "--from-url", "postgresql://u:p@localhost:9/x",
|
|
"--to-schema-datamodel", "./schema.prisma", "--script"]
|
|
]
|
|
assert fake_prisma_cli.grandchild_is_gone(within_seconds=5)
|
|
|
|
|
|
def test_migrate_diff_without_the_prisma_runner_skips_instead_of_crashing_boot(monkeypatch):
|
|
"""
|
|
Boot calls this helper directly, so an ImportError here takes the proxy down before
|
|
uvicorn starts. An install without the runner must lose the diagnostic, not the proxy.
|
|
"""
|
|
import sys
|
|
|
|
from litellm.proxy.db.check_migration import check_prisma_schema_diff_helper
|
|
|
|
monkeypatch.setitem(sys.modules, "litellm_proxy_extras.prisma_toolchain", None)
|
|
|
|
assert check_prisma_schema_diff_helper("postgresql://u:p@localhost:9/x") == (False, [])
|
|
|
|
|
|
def test_a_skipped_migration_diff_is_one_json_record_in_json_mode(
|
|
monkeypatch: pytest.MonkeyPatch, capfd: pytest.CaptureFixture[str]
|
|
) -> None:
|
|
"""
|
|
With json_logs on, the notice that the migration diff was skipped is one INFO record on stdout,
|
|
also while the loggers sit at WARNING, as they do at boot without LITELLM_LOG.
|
|
"""
|
|
from litellm.proxy.db.check_migration import check_prisma_schema_diff_helper
|
|
|
|
monkeypatch.setitem(sys.modules, "litellm_proxy_extras.prisma_toolchain", None)
|
|
monkeypatch.setattr(litellm, "json_logs", True)
|
|
monkeypatch.setattr(sys, "excepthook", sys.excepthook)
|
|
turn_on_json()
|
|
verbose_logger.setLevel(logging.WARNING)
|
|
verbose_proxy_logger.setLevel(logging.WARNING)
|
|
|
|
assert check_prisma_schema_diff_helper("postgresql://u:p@localhost:9/x") == (False, [])
|
|
|
|
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["level"], record["message"]) == (
|
|
"INFO",
|
|
"Skipping the migration diff: litellm-proxy-extras has no Prisma runner. "
|
|
"Error: import of litellm_proxy_extras.prisma_toolchain halted; None in sys.modules",
|
|
)
|