Repository navigation
fix(proxy): wait for the spend-log table before creating startup views - #41974
Conversation
On a fresh database where the migrations run in a separate job while the proxy boots with DISABLE_SCHEMA_UPDATE=true, the startup view check ran as a fire-and-forget task, used up its three 10 second retries before LiteLLM_SpendLogs existed, and died with an unretrieved exception. The spend views were never created, so the /global/spend routes returned 500 until the pod was restarted PrismaClient now holds a view setup task. It polls to_regclass for the spend-log table every 5 seconds, creates the views and loads the spend log row count once the table is there, keeps polling if an attempt raises while the schema is still settling, and logs an ERROR with the last failure if nothing worked after 15 minutes. Proxy shutdown cancels the task The spend route e2e tests for the five view-backed routes are no longer skipped and wait for the views through the harness convergence helper
|
I'll fix CI failures and address comments from users with write access. I'll skip comments containing "(aside)".
|
 |
![greptile-apps[bot]](https://avatars.githubusercontent.com/in/867647?s=60&v=4){kind=small}
| if time.monotonic() >= deadline: | ||
| self._log_view_setup_timeout(attempt, deadline_seconds) | ||
| return "timed_out" |
There was a problem hiding this comment.
If external migrations take longer than 15 minutes, this task exits and never restarts, leaving view-backed spend routes broken until proxy restart
There was a problem hiding this comment.
A fresh-database migration run takes about 90 seconds against a 15 minute cap, the old window was 10 seconds, and the ERROR names the restart
There was a problem hiding this comment.
That’s fair. With migrations taking about 90 seconds in the fresh-database case, a 15-minute bounded window is ample compared with the previous 10-second attempt, and the explicit ERROR tells operators to run migrations and restart if the deadline is exceeded. I’m withdrawing this concern.
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
… starts at boot Use contextlib.suppress for the cancelled task in stop_view_setup_task, make the legacy prisma setup test inject a plain mock for the synchronous start_view_setup_task and assert it is called, and drop the docstrings the branch added to tests
GitHub Actions
Error
…et the row count before the views
|
bugbot run |
…iew_creation_race # Conflicts: # tests/test_litellm/proxy/test_proxy_server.py
|
bugbot run |
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
There was a problem hiding this comment.
✅ Bugbot reviewed your changes and found no new issues!
Comment @cursor review or bugbot run to trigger another review on this PR
Reviewed by Cursor Bugbot for commit 327447b. Configure here.
This branch was successfully deployed
2 participants
TLDR
Problem this solves:
/global/spend*routes and the Usage tab 500 until someone restarts the podHow it solves it:
User Flow
Before: an operator's fresh helm install comes up with the Usage tab broken, and it stays broken until they restart the pod
helm installagainst an empty Postgres. The migrations Job and the proxy Deployment start at the same time, and the pod runs withDISABLE_SCHEMA_UPDATE=trueGET https://litellm-domain/health/livelinessreturns 200 while the Job is still creating tablesTask exception was never retrievedtraceback ending inrelation "LiteLLM_SpendLogs" does not exist, and nothing retries after the Job finishes 80 s laterGET https://litellm-domain/global/spendwith the master key returns 500 withrelation "MonthlyGlobalSpend" does not existin the body.GET /global/spend/keysandGET /global/spend/modelsreturn a bare 500Internal server error,GET /global/spend/tags?start_date=...&end_date=...returns 500 namingDailyTagSpend, andGET /global/spend/logsreturns 500 namingMonthlyGlobalSpendAfter: the same install serves the Usage tab on its own as soon as the migrations finish, with no restart
helm installagainst an empty Postgres. The migrations Job and the proxy Deployment start at the same time, and the pod runs withDISABLE_SCHEMA_UPDATE=trueGET https://litellm-domain/health/livelinessreturns 200 while the Job is still creating tablesWaiting for table "LiteLLM_SpendLogs" before creating the spend viewsevery 5 sGET https://litellm-domain/global/spendwith the master key returns 200 with an empty list, andGET /global/spend/keys,GET /global/spend/models,GET /global/spend/tags?start_date=...&end_date=..., andGET /global/spend/logsall return 200Relevant issues
Affected release
Linear ticket
Resolves LIT-5211
Pre-Submission checklist
Please complete all items before asking a LiteLLM maintainer to review your PR
uv run pytest tests/test_litellm/<your_test_file>.py -v. Leave the suites (make test-unit-*,make test-unit) to CI: it finishes in ~15 minutes where a laptop takes an hour or more@greptileaito re-request a review after pushing changes)Delays in PR merge?
If you're seeing a delay in your PR being merged, ping the LiteLLM Team on Slack (#pr-review).
Screenshots / Proof of Fix
Both legs ran the same rig on this machine: a fresh Postgres (
initdb+pg_ctlon a random port, empty database), two proxies of 2 uvicorn workers each booted against that empty database withDISABLE_SCHEMA_UPDATE=true(the helm ordering, where the pods come up while the migration Job is still running), the migration Job started only after both proxies answered/health/liveliness, five spend routes probed on both proxies right after the migrations finished, one real chat completion per proxy (claude-haiku-4-5through Anthropic, real spend), the same probes again 75 s later, and the old Usage page of the Admin UI opened on proxy A. The only difference between the legs is the commit the proxies were started fromBefore (8df260a)
Case 1: the spend routes on a database migrated after the proxies booted
Boot and migrate. Observed: proxy A answered
/health/liveliness26 s after launch, proxy B 1 s later, both stayed 200 through the migrations, and the migration Job exited 0 with 82 tables 52 s after it started; 30 s after that the database still had 0 viewsProbe both proxies right after the migrations. Observed, identical on A and B:
One chat completion through each proxy. Observed:
POST /v1/chat/completions -> 200on both,"content":"ok", spend writtenProbe again 75 s later. Observed: the same five 500s on both proxies, the views never appeared, and the proxy log carried
Task exception was never retrievedtwice per process from the view setup that died at bootCase 2: the old Usage page of the Admin UI on proxy A
http://127.0.0.1:$PORT_A/ui/with the master key and openhttp://127.0.0.1:$PORT_A/ui/old-usage/. Observed in the network panel:/global/spend/tags500,/global/spend/logs500,/global/spend/keys?limit=5500,/global/spend/models?limit=5500 (/global/spend/provider,/global/spend/teams,/global/spend/all_tag_names,/global/spend/end_users200 since they read tables, not views); 15 console errors, among themError fetching overall spend: ApiError: /global/spend/logs Errorrelation "MonthlyGlobalSpend" does not exist,Error fetching top tags ... relation "DailyTagSpend" does not exist,Error fetching top keys Error: Internal server error,Error fetching top models Error: Internal server errorAfter (327447b)
Case 1: the spend routes on a database migrated after the proxies booted
Boot and migrate. Observed: proxy A answered
/health/liveliness25 s after launch, proxy B 1 s later, both stayed 200 through the migrations, the migration Job exited 0 with 82 tables 52 s after it started, and all 8 views existed 1 s after thatProbe both proxies right after the migrations. Observed, identical on A and B:
One chat completion through each proxy. Observed:
POST /v1/chat/completions -> 200on both,"content":"ok"Probe again 75 s later. Observed, identical on A and B, and no
Task exception was never retrievedanywhere in either proxy log:Case 2: the old Usage page of the Admin UI on proxy A
/global/spend*request 200, including/global/spend/tags,/global/spend/logs,/global/spend/keys?limit=5,/global/spend/models?limit=5; 0 console errorslitellm_pro…row, Top Models withanthropic/claude-haiku-4-5, Spend by Provider anthropicThe tip 327447b is the merge of
maininto this branch to settle a conflict intests/test_litellm/proxy/test_proxy_server.py; its diff againstmainis the same 7 files, +411/-38, as a114af2, so the /live-pr-risk legs recorded under Live PR risk below (schema mode, default mode, restricted role) still describe this tipObservations from the run, none caused by this PR:
Type
🐛 Bug Fix
✅ Test
Design decisions
A held task instead of a wider backoff. Widening the
max_tries/max_timeoncheck_view_existswould still be a fire-and-forget task nobody awaits, so a failure would still vanish with "Task exception was never retrieved", and there is no number that covers a migrations Job of unknown length without also turning a real misconfiguration into a very long silent retry. The client now owns the task the same way it owns the DB health watchdog, so the failure path is a value the wrapper logs, shutdown can cancel it, and a second start is a no-op. The two backoff decorators stay as they were, as the inner retry for a flaky connection once the schema is thereGate on the spend-log table with
to_regclass, not on migration state. The proxy cannot know which migration set another image is applying, anddb pushsetups have no_prisma_migrationstable at all, so migration bookkeeping is the wrong signal. Prisma's advisory lock only says a migration is running right now, not whether the schema the views need exists.SELECT to_regclass($1) IS NOT NULLreturns false instead of raising when the relation is missing, so each poll is one quiet parameterized query. The probe handsto_regclassthe quoted, unqualified name"LiteLLM_SpendLogs"as the$1bind value, so Postgres resolves it through the connection'ssearch_path, the same way theCREATE VIEWstatements and the::regclassrow-count check already resolve. An earlier revision of this PR qualified the name withDATABASE_SCHEMA(defaultpublic), which broke every deployment that picks its schema with?schema=inDATABASE_URLand never setsDATABASE_SCHEMA: Prisma pointed the search_path at that schema, the migrations and the views landed there, and the probe looked inpublicforever, so the spend routes returned 500 on the fixed proxy where the merge base served them (the live A/B below shows it). Parsing?schema=out ofDATABASE_URLinstead would have reimplemented Prisma's own resolution and still missed a role whose default search_path is set on the server, so the probe follows the connectionKeep polling after a raise, and remember why.
LiteLLM_SpendLogslands early in the migration set whileLiteLLM_VerificationTokenViewreferences columns the newest migrations add, so the first attempt after the table appears can still fail mid-migration. A failed attempt logs a WARNING with the exception and the loop tries again on the next tick; the same applies to a probe that fails on a connection blip. Each attempt reports one of three things, ready, table missing, or the exception it hit, so the ERROR at the deadline says "the table never appeared, run the migrations" only when that is what happened and otherwise quotes the last exception. A first draft folded all three into a boolean and would have blamed missing migrations for a permission error. Cancellation is not caught, sinceCancelledErroris aBaseException. The row count is recorded on each attempt as soon as the table exists and before the views are created, rather than in a parallel task or only after the views succeed. An earlier revision ran it aftercheck_view_exists, so a database role without CREATE on the schema, where view creation fails on every attempt, never got the count:/sso/get/ui_settingsreportedNUM_SPEND_LOGS_ROWS0 where the merge base reported the real statistic, and the Admin UI's expensive-query guard reads that number, so a large table behind such a role would have lost the guard. The row-count query swallows its own errors and returns 0, so it cannot block the views5 seconds and 15 minutes, hardcoded. A fresh-DB migration set took about 86 s in the reproduction, so a 5 s poll costs at most one extra cheap query per tick and lands the views within seconds of the Job finishing. The 15-minute cap turns a database nobody migrated into one ERROR that names the table and says what to do, instead of an infinite loop. Neither is a knob because the correct value does not vary by deployment: anyone whose migrations take longer than 15 minutes has a bigger problem than missing views, and the failure mode past the cap is loud
The e2e routes. The five view-backed routes in
test_spend_routes.pywere skipped with a pointer to this ticket. They now run, and because the views land a few seconds after the migrations rather than before the proxy answers health, those five get a bounded re-probe (probe_until_healthy, built on the harness'sawait_convergedwith its 120 spoll_timeoutand 5 spoll_interval) while the other routes stay single-shot. The design note suggested about 60 s; 120 s was used because the reproduction's migration set took about 86 s after the proxy went live, and the harness constant already exists. That leaves roughly 19 s of margin in the worst case (86 s of migrations, a 5 s tick, and up to 10 s of inner backoff on the last failed attempt). One honest limit: the harness targets a proxy the operator starts with the documentedlitellm --config ... --port 4000command, which runs the migrations before serving, so under that boot the five routes pass with or without this fix. The un-skip proves the routes work again; the race itself is covered by the unit tests and by the live QA runChanged from the design note.
_run_view_setupis the whole loop, and it takes the poll interval and deadline as parameters with the production constants as defaults, so the tests drive the timeout path with millisecond values and assert the log without patching module constants. The probe failure is retried too, not only acheck_view_existsfailure. The probe's rows go through a PydanticTypeAdapter(tuple[Mapping[str, bool], ...])instead of a typed annotation on the untypedquery_rawresult, which keeps onereportAnyout of the basedpyright count; a malformed probe response raises inside the attempt and is retried like any other failure. The shutdown test hands the lifespan its fake client through the module'sprisma_clientglobal, the same seam the lifespan already reads, instead of patchingProxyStartupEvent._setup_prisma_clientTest expectations changed in a114af2, all in
test_prisma_client_lifecycle.py, because the probe became search_path-relative and the row count moved ahead of the views:test_view_setup_waits_for_the_spend_logs_table_before_creating_views: the probe argument is now"LiteLLM_SpendLogs"with no schema prefix, and the call order is probe, row_count, viewstest_view_setup_probes_the_configured_database_schemabecametest_view_setup_probe_resolves_through_the_connection_search_path: withDATABASE_SCHEMA=litellm_tenantset, the probe still binds the unqualified name, which is the regression test for the?schema=deploymentstest_view_setup_retries_when_view_creation_fails_mid_migrationandtest_view_setup_retries_when_the_table_probe_itself_fails: the call sequences gained therow_countstep between probe and viewstest_run_view_setup_logs_an_error_naming_the_table_on_timeout: the ERROR names"LiteLLM_SpendLogs"instead of"public"."LiteLLM_SpendLogs"test_view_setup_sets_the_row_count_even_when_view_creation_keeps_failing: acheck_view_existsthat raises on every attempt still leaves the row count set before the deadline ERRORCaveats (if any)
Low
create_view_tolerating_racealready absorbs the concurrent create, and the merge base rancheck_view_existsonce per worker too. Not fixed: electing one worker needs shared state the proxy does not hold at bootLiteLLM_VerificationTokenViewcan be created between the migration that addstpd_limitand the one that addstotal_spend, so on a fresh install it can lacktotal_spendthe way it already does on every upgraded deployment; nothing in the proxy selects from that view, key auth reads the base table. Not fixed: pre-existing on every upgraded deployment, and a view refresh belongs in a migration, not in the startup taskstop_view_setup_taskswallows aCancelledErroraimed at the shutdown coroutine itself, the same waystop_db_health_watchdog_taskdoes right above it; only shutdown is affected. Not fixed: re-raising there would turn a cancelled shutdown into an error log on the one path that mirrors the watchdog'scheck_view_existsstill readsDATABASE_SCHEMA(defaultpublic) for its pg_views lookup, so a?schema=URL without that variable re-issues the CREATE VIEW statements on every boot; the live schema-mode leg shows the restart absorbing them with no WARNING, and the merge base does the same. Not fixed: pre-existing, and the gate itself no longer depends on that variableself.db.query_raw, so on a read-replica setup a lagging replica can answer "missing" one tick after the writer has the table, which only delays the views by 5 s. Not driven live: the rig has no replicaexceptatstop_db_health_watchdog_taskon the PR's merge commit (utils.py:6352 there, 6339 at the tip); that function predates this PR (fix(proxy): self-heal Prisma connection for auth and runtime #21706) and this diff does not touch it. Not fixed here: cleaning up a function this PR does not change belongs in its own changeci/circleci: google_generate_content_endpoint_testing(job 2193727) is red, and every one of its 6 errors is the session fixture intests/unified_google_tests/conftest.pyfailing withRuntimeError: LiteLLM proxy failed to startbecause feat(proxy)!: refuse to start with an unset, empty, or publicly known master key #42019 (mainb6dd3d9, merged after this branch's original merge base and pulled in by the merge commit) refuses the test config'smaster_key: sk-1234withUnsafeMasterKeyError. The same test errors the same way at the merge base 8df260a with none of this PR's code (run locally,LiteLLM proxy refused to start: the master key is a publicly known default), the lastmainpipeline (89901, at 1fcef68) predates feat(proxy)!: refuse to start with an unset, empty, or publicly known master key #42019 somain's next scheduled run reds too, and this PR touches nothing undertests/unified_google_tests. Tracked in LIT-8226. Not fixed here: the fix belongs to that suite's fixture, not to this PRQA runbook
Prerequisites: a fresh Postgres and a proxy booted with
DATABASE_URLandDISABLE_SCHEMA_UPDATE=truebeforepython litellm/proxy/prisma_migration.pyis run against that database (the helm ordering); nothing provider-side is neededGET http://localhost:4000/health/livelinessreturns 200, then run the migrationsGET http://localhost:4000/global/spendwith the master key returns 200 with a JSON listGET http://localhost:4000/global/spend/keyswith the master key returns 200 instead of a bare 500Internal server errorGET http://localhost:4000/global/spend/modelswith the master key returns 200 instead of a bare 500Internal server errorGET http://localhost:4000/global/spend/tags?start_date=<yesterday>&end_date=<today>with the master key returns 200 instead of 500relation "DailyTagSpend" does not existGET http://localhost:4000/global/spend/logswith the master key returns 200 instead of 500relation "MonthlyGlobalSpend" does not existLive PR risk (327447b)
Every leg below ran the real proxy (2 uvicorn workers, real Postgres) on both sides of the change; the a114af2 legs stand for this tip because the merge commit added nothing to the PR's diff
Breaking
None. The diff adds
start_view_setup_task,stop_view_setup_task, and the private_run_view_setup,_attempt_view_setup,_log_view_setup_timeout,_view_setup_gate_table_presenttoPrismaClientplus four module constants; no existing signature, response field, config key, env var, or DB column changesBackward incompatible
None observed. On a database that is already migrated when the proxy boots (the common case) the views are created on the first attempt and the routes answer the same as before: the default-mode legs (base b8d837b vs head a114af2, fresh database migrated by the proxy itself, then a restart against the migrated database) returned 200 with the same bodies on every
/global/spend*route on both sides, and/sso/get/ui_settingskept its shapeRegression risk
self.db.query_raw, so a lagging replica can answer "missing" one 5 s tick after the writer has the table, which only delays the views. Inferred from the code, not drivencreate_view_tolerating_race, no error on either workerDependency graph
start_view_setup_taskfromproxy_startup_event: verified live in both legs of the proof abovestop_view_setup_taskfrom the shutdown path: unit-tested intest_prisma_client_lifecycle.py; the QA proxies shut down cleanly when stoppedspend_logs_row_count->ui_sso.py->GET /sso/get/ui_settings(NUM_SPEND_LOGS_ROWS): verified live, 0 on the merge base for the life of the process, -1 at the tip on a fresh never-analyzed table (Postgresreltuples), a real count after the first analyze/global/spend/*: verified live through the old Usage page screenshots abovecheck_view_existsreadingDATABASE_SCHEMAfor itspg_viewslookup: pre-existing; the schema-mode legs (?schema=lit5211in the URL, base b8d837b vs head a114af2) created all 8 views underlit5211and answered 200 on every route on both sides, on the fresh boot and on the restartpublic, migrations run aspostgres): all five routes 500 identically on base b8d837b, on 1b8f704, and on head a114af2, so a role that cannot create views is unchanged by this PRNot verified
DATABASE_SCHEMAexported explicitly together with a?schema=URL that names a different schemaFinal Attestation
Link to Devin session: https://app.devin.ai/sessions/ca016fcfcb0e45a0814ed91336e594d7
Requested by: @mateo-berri