fix(passthrough): schedule spend logging via durable logging worker#31485
Conversation
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 Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
|
Generated by Claude Code |
Greptile SummaryThis PR moves pass-through spend logging onto the shared logging worker. The main changes are:
Confidence Score: 4/5Medium 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
What T-Rex did
Reviews (2): Last reviewed commit: "fix(passthrough): schedule spend logging..." | Re-trigger Greptile |
|
bugbot run Generated by Claude Code |
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 d702ce6. Configure here.
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
@greptileaiand received a Confidence Score of at least 4/5 before requesting a maintainer reviewScreenshots / 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
/geminipass-through route:Expect
call_type: "pass_through_endpoint", the gemini model,spend > 0, andstatus: "success". Repeat the loop a few dozen times in aforloop 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_tasksset and drains on shutdown viaflush/stop/clear_queueplus anatexithandler, 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 byLoggingWorkerand 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.pyasserting thatchunk_processorhands its logging coroutine toGLOBAL_LOGGING_WORKER.ensure_initialized_and_enqueue(rather than a bare task), on both normal completion and client-disconnect. Both fail against the pre-fixasyncio.create_taskcode (ensure_initialized_and_enqueuecalled 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_taskcalls. Those coroutines are enqueued onGLOBAL_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_processorfinally-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.