fix(passthrough): record real TTFT and start_time for streaming requests - #30384
fix(passthrough): record real TTFT and start_time for streaming requests#30384songkuan-zheng wants to merge 3 commits into
Conversation
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
Greptile SummaryThis PR fixes two interacting timing bugs in
Confidence Score: 5/5Safe to merge — the change is confined to two write-once timestamp assignments inside a single static method, with no effect on the forwarded bytes or existing downstream logging contracts. Both mutations are strictly additive: they only fill fields that were previously unset (or set too late), and existing non-None values are preserved by the No files require special attention.
|
| Filename | Overview |
|---|---|
| litellm/proxy/pass_through_endpoints/streaming_handler.py | Adds start_time override from litellm_logging_obj.start_time when it's earlier, and records completion_start_time on the first chunk in both loop branches; logic is correct, tz-mismatch is guarded with try/except, and _update_completion_start_time is confirmed to exist on LiteLLMLoggingObj. |
| tests/test_litellm/proxy/pass_through_endpoints/test_streaming_handler.py | New mock-only test file covering all 4 scenarios: start_time override when logging obj is earlier, write-once semantics when caller is earlier, first-chunk TTFT recording, and no-overwrite when already set; _build_response_with_chunks is a plain def, _drain uses asyncio.run, and both assertion-before-equality guards are in place. |
Reviews (5): Last reviewed commit: "chore: add Co-authored-by trailer for at..." | Re-trigger Greptile
![greptile-apps[bot]](https://avatars.githubusercontent.com/in/867647?s=60&v=4){kind=small}
Greptile SummaryThis PR fixes two interacting timing bugs in
Confidence Score: 4/5The production fix is a narrow, correct change to two fields on an existing logging object — no new dependencies, no schema changes, no auth-path involvement. The test-only concerns do not affect runtime behavior. Both production changes are small, write-once, and isolated to the logging side of chunk_processor. The datetime comparisons are safe because all timestamps in this path use naive datetime.now(). The two test issues (unnecessary asyncio.run wrapper and missing guard before captured_start_time access) are low-stakes quality items that do not affect what the tests verify in practice. The test file could use minor hardening of its assertions, but no production files require additional attention.
|
| Filename | Overview |
|---|---|
| litellm/proxy/pass_through_endpoints/streaming_handler.py | Adds two targeted fixes to chunk_processor: override start_time with litellm_logging_obj.start_time when it's earlier, and record completion_start_time on the first chunk. Logic is correct and consistent with the rest of the file's datetime usage. |
| tests/test_litellm/proxy/pass_through_endpoints/test_streaming_handler.py | New test file with 4 mock-only tests covering the two timing fixes. Tests rely on asyncio.run cleanup running the asyncio.create_task'd logging coroutine; works in practice but the assertion pattern is fragile (see inline comment). |
Reviews (2): Last reviewed commit: "fix(passthrough): record real TTFT and s..." | Re-trigger Greptile
| async def _collect(): | ||
| return [x async for x in gen] | ||
|
|
||
| return asyncio.run(_collect()) | ||
|
|
||
|
|
||
| def test_chunk_processor_uses_logging_obj_start_time_when_earlier(monkeypatch): |
There was a problem hiding this comment.
_build_response_with_chunks is async for no reason, and the asyncio.run call is unnecessary
The helper function doesn't await anything — it just constructs a MagicMock and sets an attribute. Wrapping it in asyncio.run(...) creates a new event loop, completes immediately, then tears it down, which is pointless overhead and adds noise. A plain def returning the mock directly would be cleaner and would avoid any cross-loop confusion if async generator semantics ever change between Python versions.
Note: If this suggestion doesn't match your team's coding style, reply to this and let me know. I'll remember it for next time!
| "Handler must override the later caller-supplied start_time with the " | ||
| "earlier logging-obj start_time." | ||
| ) | ||
|
|
||
|
|
||
| def test_chunk_processor_keeps_caller_start_time_when_earlier(monkeypatch): | ||
| """When the caller-supplied start_time is already earlier than the |
There was a problem hiding this comment.
captured_start_time["start_time"] raises KeyError instead of AssertionError if the logging task never ran
chunk_processor's finally block fires the logging coroutine via asyncio.create_task, which only runs during asyncio.run's cleanup phase (_cancel_all_tasks → gather). If that task is cancelled before executing any of its body (e.g., on a Python version with different cleanup ordering), captured_start_time stays empty and captured_start_time["start_time"] raises KeyError rather than a meaningful AssertionError. A guard like assert "start_time" in captured_start_time, "logging task never ran" before the equality check would give a much clearer failure signal. The same pattern applies in test_chunk_processor_keeps_caller_start_time_when_earlier.
|
Thanks for the contribution! A couple of things to address before this is ready for merge:
Once those are in, we'll take another look! |
…erriAI#30384) Four P2 threads resolved: 1. **tz-aware vs tz-naive comparison can crash the stream** (`streaming_handler.py:51`). Wrapped the `true_start < start_time` comparison in try/except for `TypeError`. tzinfo mismatch now skips the override silently rather than propagating before the first chunk is yielded. 2. **Stale line-number reference** (`streaming_handler.py:68`). Dropped the `litellm_logging.py:1834-1837` pointer and rephrased the comment to describe the fallback semantically — no line number to rot. 3. **`_build_response_with_chunks` was `async` for no reason** (test_streaming_handler.py:37). Plain `def`, removed `asyncio.run(...)` wrapper at all four call sites. 4. **`captured_start_time["start_time"]` could raise `KeyError` instead of an informative assertion** if the logging task never executed. Added an explicit `assert "start_time" in ...` with a clear message before the value check, in both affected tests. 4/4 pass locally.
|
@Sameerlite — done in
4/4 pass locally. |
Pass-through streaming requests (/v1/messages, /vertex_ai/*, /gemini/*, /cohere/*, /assemblyai/*, /openai/*, /cursor/*) all share PassThroughStreamingHandler.chunk_processor, which had two timing bugs that interacted to collapse spend_logs.completionStartTime onto spend_logs.endTime — making the streaming phase (endTime - completionStartTime) round to roughly zero and TTFT effectively soak up the entire request duration for every pass-through streaming row. Root causes 1. `start_time` arg captured too late. The caller's start_time originates in BaseAnthropicMessagesStreamingIterator.__init__, which runs AFTER the upstream HTTP response has already been received. SpendLogs.startTime therefore reflects "moment we started reading the stream", not "moment the client request entered the proxy" — the real TTFT window is silently subtracted from Duration. 2. First-chunk arrival never recorded. The chunk loop yielded bytes without updating litellm_logging_obj.completion_start_time. The fallback at litellm_logging.py:1834-1837 sets completion_start_time = end_time, collapsing TTFT onto Duration. Fix - Use litellm_logging_obj.start_time when it's earlier than the caller-supplied start_time (true request-entry timestamp). - Record completion_start_time on the first emitted chunk. Both fields are write-once: existing values are preserved. Blast radius: all pass-through endpoints — they all flow through this single chunk_processor.
…erriAI#30384) Four P2 threads resolved: 1. **tz-aware vs tz-naive comparison can crash the stream** (`streaming_handler.py:51`). Wrapped the `true_start < start_time` comparison in try/except for `TypeError`. tzinfo mismatch now skips the override silently rather than propagating before the first chunk is yielded. 2. **Stale line-number reference** (`streaming_handler.py:68`). Dropped the `litellm_logging.py:1834-1837` pointer and rephrased the comment to describe the fallback semantically — no line number to rot. 3. **`_build_response_with_chunks` was `async` for no reason** (test_streaming_handler.py:37). Plain `def`, removed `asyncio.run(...)` wrapper at all four call sites. 4. **`captured_start_time["start_time"]` could raise `KeyError` instead of an informative assertion** if the logging task never executed. Added an explicit `assert "start_time" in ...` with a clear message before the value check, in both affected tests. 4/4 pass locally.
Co-authored-by: songkuan-zheng <songkuan-zheng@users.noreply.github.com>
98c468f to
8d6471b
Compare
|
|
|
Thanks for working on this! Triggering a fresh Greptile review. The previous pass (4/5) had 4 unresolved P2 issues — if you've addressed them in the latest commit, the fresh review should reflect that:
|
|
@Sameerlite — all 4 P2s from the previous Greptile pass were resolved in P2-A (tz-aware vs naive datetime comparison risk) — wrapped the true_start = getattr(litellm_logging_obj, "start_time", None)
if isinstance(true_start, datetime):
try:
if not isinstance(start_time, datetime) or true_start < start_time:
start_time = true_start
except TypeError:
passP2-B (stale line reference) — updated the comment to point at the current P2-C ( P2-D ( |
|
Thanks so much for the persistence on this one, @songkuan-zheng — the timing fixes look solid and we appreciate the detailed explanations!\n\nA couple of things to get this over the finish line:\n\n1. Greptile has 2 unresolved P2 threads on the latest commit — could you take a look and either address them or reply to close them out?\n - |
|
@Sameerlite thanks for the follow-up! Both P2s you mentioned were actually addressed in P2 — def _build_response_with_chunks(chunks):
"""Wrap a list of bytes chunks into an httpx.Response-shaped mock that
yields them via aiter_bytes()."""
async def _aiter_bytes():
for c in chunks:
yield c
response = MagicMock(spec=httpx.Response)
response.aiter_bytes = _aiter_bytes
response.headers = {}
return responseP2 — assert (
"start_time" in captured_start_time
), "logging task never reached the route_streaming_logging_to_handler stub"
assert captured_start_time["start_time"] == earlier, (
"Handler must override the later caller-supplied start_time with the "
"earlier logging-obj start_time."
)A cleanup-order regression now surfaces as Proof — pytest output on current HEADEach test pins one branch of the spec:
|
|
@ishaan-jaff friendly bump — open 15 days, MERGEABLE with green CI. Streaming passthrough requests were recording |
|
@Sameerlite — circling back on this one with the evidence you asked for. Both the P2 fixes ( 1. Before/after — new tests run against the OLD
|
|
@Sameerlite friendly ping — evidence + before/after in the comment just above. P2s addressed, ready for another look 🙏 |
3 participants
Relevant issues
No existing issue. Two interacting timing bugs in
PassThroughStreamingHandler.chunk_processorcollapse SpendLogscompletionStartTimeontoendTimefor every pass-through streaming row.Type
🐛 Bug Fix
Pre-Submission checklist
make testlocallyDescription
Pass-through streaming requests (
/v1/messages,/vertex_ai/*,/gemini/*,/cohere/*,/assemblyai/*,/openai/*,/cursor/*) all flow throughPassThroughStreamingHandler.chunk_processor. Two bugs interact:1.
start_timearg captured too late. The caller'sstart_timeoriginates inBaseAnthropicMessagesStreamingIterator.__init__, which runs AFTER the upstream HTTP response has already been received.SpendLogs.startTimetherefore reflects "moment we started reading the stream", not "moment the client request entered the proxy" — the real TTFT window is silently subtracted from Duration.2. First-chunk arrival never recorded. The chunk loop yielded bytes without updating
litellm_logging_obj.completion_start_time. The fallback atlitellm_logging.py:1834-1837setscompletion_start_time = end_time, collapsing TTFT onto Duration.Fix
litellm_logging_obj.start_timewhen it's earlier than the caller-suppliedstart_time(true request-entry timestamp).completion_start_timeon the first emitted chunk.Both fields are write-once: existing values are preserved.
Blast radius: all pass-through endpoints — they all flow through this single
chunk_processor.Test plan
New
tests/test_litellm/proxy/pass_through_endpoints/test_streaming_handler.pywith 4 cases:test_chunk_processor_uses_logging_obj_start_time_when_earlier— main fixtest_chunk_processor_keeps_caller_start_time_when_earlier— write-once semanticstest_chunk_processor_records_completion_start_on_first_chunk— TTFT capturetest_chunk_processor_does_not_overwrite_existing_completion_start— write-once for TTFTAll 4 pass.
Co-authored-by: songkuan-zheng songkuan-zheng@users.noreply.github.com