Skip to content

fix(passthrough): schedule spend logging via durable logging worker#31485

Merged
mateo-berri merged 1 commit into
litellm_internal_stagingfrom
litellm_passthrough_spend_log_durability
Jun 27, 2026
Merged

fix(passthrough): schedule spend logging via durable logging worker#31485
mateo-berri merged 1 commit into
litellm_internal_stagingfrom
litellm_passthrough_spend_log_durability

Conversation

@mateo-berri

@mateo-berri mateo-berri commented Jun 27, 2026

Copy link
Copy Markdown
Collaborator

Relevant issues

Investigation of a flaky vertex pass-through e2e test (the one that polls /spend/logs?request_id=<x-litellm-call-id> for a costed row and often times out at 240s even though the write should take seconds)

Linear ticket

Pre-Submission checklist

  • I have added meaningful tests
  • My PR passes all CI/CD checks (e.g., lint, format, unit tests)
  • My PR's scope is as isolated as possible; it only solves 1 specific problem
  • I have requested a Greptile review by commenting @greptileai and received a Confidence Score of at least 4/5 before requesting a maintainer review

Screenshots / Proof of Fix

This is a logging-durability fix; the cleanest live proof is to drive a real pass-through call through a proxy on localhost:4000 and confirm the SpendLogs row lands, hitting a real provider so it costs real money. With a Gemini key configured for the /gemini pass-through route:

  1. Start the proxy
python litellm/proxy/proxy_cli.py --config litellm/proxy/dev_config.yaml --detailed_debug --reload --use_v2_migration_resolver 2>&1 | tee litellm.log
  1. Send a native Gemini pass-through call and capture the call id
CALL_ID=$(curl -sS -D /dev/stderr -o /tmp/resp.json \
  -X POST "http://localhost:4000/gemini/v1beta/models/gemini-2.5-flash:generateContent" \
  -H "Authorization: Bearer $LITELLM_KEY" \
  -H "Content-Type: application/json" \
  -d '{"contents":[{"parts":[{"text":"Say hello in one word"}]}]}' \
  2>&1 1>/dev/null | tr -d '\r' | awk -F': ' 'tolower($1)=="x-litellm-call-id"{print $2}')
echo "call_id=$CALL_ID"
  1. A couple seconds later, confirm a costed row exists for that call id
curl -sS "http://localhost:4000/spend/logs?request_id=$CALL_ID" \
  -H "Authorization: Bearer $LITELLM_MASTER_KEY" | jq '.[0] | {request_id, call_type, model, spend, status}'

Expect call_type: "pass_through_endpoint", the gemini model, spend > 0, and status: "success". Repeat the loop a few dozen times in a for loop to confirm the row shows up every time rather than intermittently going missing.

Type

🐛 Bug Fix

Changes

Pass-through success logging was scheduled with a bare asyncio.create_task(...) whose return value is discarded, in three places: the non-streaming HTTP path (pass_through_endpoints.py), the streaming finally-block (streaming_handler.py), and the vertex live websocket path. The asyncio event loop keeps only a weak reference to such tasks, so under GC or load pressure the task can be collected before it finishes writing the SpendLogs row. The request then returns 2xx to the caller while its spend log silently never gets written. This is the most likely cause of the flaky vertex pass-through e2e test, and a rare but real source of unbilled pass-through spend in prod.

Worth being precise about the blast radius: for pass-through, the budget/cost increment rides in the same dispatched success-logging callback as the SpendLogs row (it dispatches to _PROXY_track_cost_callback -> db_spend_update_writer.update_database, which both writes the row and bumps key/team/user spend). So a dropped task loses both the audit row and the aggregate spend; the cost never even reaches the durable spend queue. Normal (non-pass-through) completions are unaffected because their callback is awaited inline and reliably enters that durable queue; pass-through is exactly the path that lacked that guarantee.

The fix routes those coroutines through GLOBAL_LOGGING_WORKER.ensure_initialized_and_enqueue(...), the same async logging worker the SDK completion path already uses (litellm/utils.py, caching_handler.py). The worker keeps a strong reference to each in-flight task in its _running_tasks set and drains on shutdown via flush/stop/clear_queue plus an atexit handler, so the spend write can no longer be dropped mid-flight.

Tradeoffs

This deliberately reuses the existing best-effort worker rather than building a new durable-delivery path, so the pros and cons are worth being explicit about.

Pros. It fixes the GC-drop without changing the non-blocking behavior pass-through wants, since the caller's response is still returned before logging runs. It inherits real shutdown draining instead of losing in-flight tasks on process exit. It bounds concurrency and applies a per-coroutine timeout, so a stuck log can't pile up unbounded. And it follows an established in-repo pattern (the same _running_tasks + add_done_callback(discard) shape used by LoggingWorker and the akto guardrail) rather than hand-rolling another bespoke task set that would need its own shutdown drain to be correct.

Cons. The logging worker is explicitly best-effort with a bounded queue, so under sustained overload it aggressively clears and can still drop logs; this turns a guaranteed-drop-under-GC into a much-less-likely drop-under-overload, but it is not at-least-once delivery. It also swallows per-task exceptions internally, so this does not fix the separate issue where a failing cost-calc / payload-build in the pass-through handlers logs-and-returns and the row never gets queued; that silent-swallow path is worth a follow-up. And pass-through spend logging now shares the process-global worker's queue and concurrency budget with all other async callback logging, so their backpressure is coupled.

Truly durable at-least-once spend logging (persist-before-return outbox + reconciler keyed on request_id) would be a larger, separate change; this PR is the minimal fix for the actual flake and the GC-drop behind it.

Tests

Added two regression tests to test_streaming_handler_interrupt.py asserting that chunk_processor hands its logging coroutine to GLOBAL_LOGGING_WORKER.ensure_initialized_and_enqueue (rather than a bare task), on both normal completion and client-disconnect. Both fail against the pre-fix asyncio.create_task code (ensure_initialized_and_enqueue called 0 times) and pass after the change.


Note

Medium Risk
Touches billing/audit paths for pass-through only; behavior stays async and non-blocking but now shares the global worker’s bounded queue and overload behavior with other logging.

Overview
Pass-through success/spend logging no longer uses discarded asyncio.create_task calls. Those coroutines are enqueued on GLOBAL_LOGGING_WORKER.ensure_initialized_and_enqueue, matching the SDK completion path so in-flight log tasks keep strong references and can drain on shutdown.

Scope: non-streaming HTTP success logging, streaming chunk_processor finally-block (including client disconnect), and Vertex live WebSocket success logging.

Tests: two regressions assert streaming logging is enqueued on the worker for normal completion and mid-stream disconnect.

Reviewed by Cursor Bugbot for commit d702ce6. Bugbot is set up for automated code reviews on this repo. Configure here.

Pass-through success logging was scheduled with a bare asyncio.create_task
whose return value was discarded, for non-streaming HTTP, streaming, and the
vertex live websocket paths. The event loop keeps only a weak reference to such
tasks, so under GC or load the task can be collected before it finishes writing
the SpendLogs row; a request then returns 2xx to the caller yet never produces a
costed spend log. This is the most likely cause of the flaky vertex passthrough
e2e test and a rare real source of unbilled pass-through spend.

Route these coroutines through GLOBAL_LOGGING_WORKER.ensure_initialized_and_enqueue
instead, matching how the SDK completion path already enqueues async logging. The
worker holds a strong reference in its _running_tasks set and drains on shutdown
via flush/stop/clear_queue and the atexit handler, so the write can no longer be
dropped mid-flight.
@codecov

codecov Bot commented Jun 27, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 80.00000% with 1 line in your changes missing coverage. Please review.

Files with missing lines Patch % Lines
...y/pass_through_endpoints/pass_through_endpoints.py 66.66% 1 Missing ⚠️

📢 Thoughts on this report? Let us know!

@mateo-berri

Copy link
Copy Markdown
Collaborator Author

@greptileai


Generated by Claude Code

@greptile-apps

greptile-apps Bot commented Jun 27, 2026

Copy link
Copy Markdown
Contributor

Greptile Summary

This PR moves pass-through spend logging onto the shared logging worker. The main changes are:

  • Enqueues non-streaming HTTP pass-through success logging through GLOBAL_LOGGING_WORKER
  • Enqueues websocket pass-through success logging through the same worker path
  • Routes streaming completion and disconnect logging through the worker instead of bare background tasks
  • Adds focused tests for streaming logging handoff on normal completion and client disconnect

Confidence Score: 4/5

Medium risk: the change is isolated to pass-through billing/audit logging and preserves asynchronous response behavior while relying on the existing shared worker’s bounded best-effort semantics.

The implementation follows an established in-repo worker pattern and adds focused regression coverage for the streaming paths, but it touches spend logging and still inherits overload/drop behavior from the shared logging queue.

litellm/proxy/pass_through_endpoints/pass_through_endpoints.py, litellm/proxy/pass_through_endpoints/streaming_handler.py, and tests/test_litellm/proxy/pass_through_endpoints/test_streaming_handler_interrupt.py

T-Rex T-Rex Logs

What T-Rex did

  • Ran the nonstream-passthrough-logging-worker verification and reviewed the before/after logs to confirm the task-creation vs enqueue behavior shifted as expected; before showed create_task_call_count: 1 and worker_enqueue_call_count: 0, while after showed create_task_call_count: 0 and worker_enqueue_call_count: 1.
  • Executed the streaming-passthrough-logging-worker verification and observed the post-change counts, including asyncio.create_task going from 1 to 0 and worker_enqueue growing to 1, with worker_arg_is_coroutine set to True.
  • Executed the websocket-passthrough-logging-worker verification and noted changes in create_task_success_handler, ensure_initialized_and_enqueue, worker_received_success_coro, create_task_total, and post_call_success_hook; the harness file trex-artifacts/websocket_passthrough_logging_worker_harness.py was saved for inspection.

View all artifacts

T-Rex Ran code and verified through T-Rex

Reviews (2): Last reviewed commit: "fix(passthrough): schedule spend logging..." | Re-trigger Greptile

@mateo-berri

Copy link
Copy Markdown
Collaborator Author

bugbot run


Generated by Claude Code

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

✅ 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 d702ce6. Configure here.

@mateo-berri mateo-berri marked this pull request as ready for review June 27, 2026 01:31
@mateo-berri mateo-berri requested a review from yuneng-berri June 27, 2026 01:31
@mateo-berri mateo-berri merged commit 4157f3b into litellm_internal_staging Jun 27, 2026
127 checks passed
@mateo-berri mateo-berri deleted the litellm_passthrough_spend_log_durability branch June 27, 2026 01:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants