GhishaDev · songkuan-zheng · May 18, 2026 · May 18, 2026
diff --git a/e2e/cases/13_passthrough_streaming_ttft.md b/e2e/cases/13_passthrough_streaming_ttft.md
@@ -0,0 +1,123 @@
+# Case 13 — Pass-through streaming TTFT must reflect real time-to-first-token
+
+## Goal
+
+Regression guard for two interacting bugs in
+`litellm/proxy/pass_through_endpoints/streaming_handler.py` that
+together collapsed `spend_logs.completionStartTime` onto
+`spend_logs.endTime` (off by ~1ms of clock resolution, not literally
+identical), making the streaming phase
+(`endTime - completionStartTime`) round to roughly zero and TTFT
+effectively soak up the entire request duration — for every streaming
+request through any pass-through endpoint (`/v1/messages`,
+`/vertex_ai/*`, `/gemini/*`, `/cohere/*`, etc.).
+
+## Origin
+
+Reported by an operator looking at the dashboard: for streaming calls
+through `/v1/messages` (Anthropic pass-through), `Duration (s)` and
+`TTFT (s)` columns showed near-identical values (off by ≤1 ms) —
+including on multi-second completions where TTFT physically can't be
+the entire request time.
+
+## Root cause (verified end-to-end)
+
+Two bugs in the shared `PassThroughStreamingHandler.chunk_processor`:
+
+1. **`start_time` is captured too late.** The `start_time` argument
+   handed to `chunk_processor` originates in
+   `BaseAnthropicMessagesStreamingIterator.__init__`, which runs
+   *after* the upstream HTTP response has already been received.
+   So `SpendLogs.startTime` reflects "moment we started reading the
+   stream", not "moment the client request entered the proxy" — the
+   true TTFT window is silently subtracted from `Duration`.
+
+2. **`completion_start_time` is never recorded.** The original chunk
+   loop yielded bytes to the client and collected them for logging,
+   but never noted when the first byte arrived. With
+   `litellm_logging_obj.completion_start_time` left as `None`, the
+   fallback at `litellm_logging.py:1834-1837` sets it to `end_time`
+   — collapsing `completionStartTime` onto `endTime` and zeroing out
+   the streaming phase.
+
+Both bugs hide each other. Fixing only #2 leaves you with `TTFT ≈ 0`
+and `Duration` deflated by ~TTFT; fixing only #1 leaves `TTFT ==
+Duration`. Both must be fixed for the math to come out right.
+
+## Numerical evidence (Anthropic claude-sonnet-4-6, 200-word stream)
+
+| State | Duration | TTFT | streaming_phase | curl wall-clock |
+|---|---|---|---|---|
+| Bug present | 6528 ms | 6527 ms | 1 ms | 8769 ms |
+| Bug #2 fixed only | 7698 ms | 14 ms | 7684 ms | 9893 ms |
+| Both fixed | **8496 ms** | **2373 ms** | **6123 ms** | 8551 ms |
+| Control (`/v1/chat/completions` transform, same model + prompt) | 8143 ms | 2071 ms | 6072 ms | 8214 ms |
+
+After the fix, the pass-through path is within ~5% of the transform
+path on the same upstream model — the two should report the same
+streaming behavior because the underlying HTTP request is the same.
+
+## Preconditions
+
+- `e2e/tools/proxy status` reports `ready`
+- `ANTHROPIC_API_KEY` set (this case uses a real ~200-word completion;
+  cost ≈ $0.005 per run)
+
+## Steps
+
+```bash
+bash e2e/cases/data/13_passthrough_streaming_ttft.sh
+echo "exit=$?"
+```
+
+The fixture:
+
+1. Sends a streaming POST to `/v1/messages` with `max_tokens=400` and a
+   prompt that asks for a 200-word essay, so the stream runs for
+   several seconds.
+2. Sends an equivalent streaming POST to `/v1/chat/completions` as a
+   parity reference for the transform path.
+3. Waits 5 s for the async spend-logger to flush, then queries the
+   two newest spend_logs rows.
+4. Asserts on the `anthropic_messages` row:
+   - `streaming_phase_ms > 1000`
+   - `ttft_ms > 300`
+   - `ttft_ms < duration_ms / 2`
+5. Soft-warns if `anthropic_messages.ttft` differs from `acompletion.ttft`
+   by more than 3× (provider cold-start variance can hit 2×, so this
+   is informational, not a fail).
+
+## Expected — GREEN (after fix lands)
+
+```
+A (/v1/messages):           wall=8551ms, bytes=4789
+B (/v1/chat/completions):   wall=8214ms, bytes=5660
+
+spend_logs rows:
+  anthropic_messages      duration=  8496ms  ttft=  2373ms  streaming=  6123ms
+  acompletion             duration=  8143ms  ttft=  2071ms  streaming=  6072ms
+
+PASS: passthrough streaming TTFT is recorded correctly.
+  /v1/messages    duration=8496ms ttft=2373ms streaming=6123ms
+```
+
+## Failure modes
+
+| Symptom | Likely cause |
+|---|---|
+| `FAIL [assertion 1]: streaming_phase=1ms` | Bug #2 regressed — first-chunk arrival not recorded; `completion_start_time` fell back to `end_time` |
+| `FAIL [assertion 2]: ttft=14ms` | Bug #1 regressed — `start_time` is captured at iterator `__init__` again, after upstream response; need the `litellm_logging_obj.start_time` override |
+| `FAIL [assertion 3]: ttft > duration/2` | One of the two bugs has partially regressed; check both `chunk_processor` entry-time and first-chunk recording |
+| `WARN: TTFT parity off — ...ratio=...` | Soft signal only — usually means the Anthropic path hit a cold cache on this run; rerun once to confirm |
+| `FAIL: no anthropic_messages row` | Async spend logger backed up — increase the `sleep 5` to 10 |
+
+## Cross-reference
+
+- `litellm/proxy/pass_through_endpoints/streaming_handler.py` —
+  fix lives at the top of `chunk_processor`'s `try:` block
+- Case 12 — guards the cost-calc path for dashboard-added deployments
+- Case 11 — guards observability for failure logging
+- This case (13) — guards observability for streaming latency
+
+All four (10/11/12/13) green means the cost + observability pipeline
+is trustworthy end-to-end for both transform and pass-through paths.
diff --git a/e2e/cases/README.md b/e2e/cases/README.md
@@ -22,6 +22,7 @@ Humans can execute them too — every step is a concrete shell command.
 | 10 | `10_cost_breakdown_cache_missing.md` | (none — direct calc) | `cost_breakdown.cache_read_cost` / `cache_creation_cost` not silently `None` | — |
 | 11 | `11_error_information_message_populated.md` | (none — invalid key) | `spend_logs.metadata.error_information.error_message` non-empty on failure | ✓ |
 | 12 | `12_custom_pricing_must_honor_cache_tokens.md` | (none — direct calc) | `custom_cost_per_token` short-circuit must include cache pricing (Bug #2 root cause) | — |
+| 13 | `13_passthrough_streaming_ttft.md` | Anthropic | `/v1/messages` streaming `completionStartTime` must reflect first-chunk arrival, not collapse to `endTime` (streaming_phase ≈ 0) | ✓ |
 
 ## How to invoke
 

diff --git a/e2e/cases/data/13_passthrough_streaming_ttft.sh b/e2e/cases/data/13_passthrough_streaming_ttft.sh
@@ -0,0 +1,164 @@
+#!/usr/bin/env bash
+# Regression fixture for Case 13 — passthrough streaming TTFT must be a real
+# time-to-first-token, not a copy of total Duration.
+#
+# Makes a streaming request to /v1/messages (Anthropic passthrough), waits for
+# the spend_logs row to flush, and asserts:
+#
+#   1. streaming_phase_ms = endTime - completionStartTime > 1000 ms
+#      (server actually streamed; this catches the "1ms streaming phase"
+#       symptom where completion_start_time gets set to end_time)
+#   2. ttft_ms = completionStartTime - startTime > 300 ms
+#      (first chunk wasn't recorded at request entry time either)
+#   3. ttft_ms < 0.5 * duration_ms
+#      (TTFT shouldn't dominate Duration on a long-enough stream)
+#
+# Side-by-side parity vs /v1/chat/completions: both paths' TTFTs should be
+# within 3x of each other (cache miss + LLM warm-up varies).
+#
+# Cost ~ $0.005 per run.
+
+set -eu
+
+PROXY_URL="${PROXY_URL:-http://localhost:4011}"
+DB_CONTAINER="${DB_CONTAINER:-litellm-e2e-db}"
+DB_USER="${DB_USER:-litellm}"
+DB_NAME="${DB_NAME:-litellm}"
+MASTER_KEY="${MASTER_KEY:-sk-e2e-test}"
+
+# Unique seed so we can find exactly these requests later if needed
+SENTINEL=$(date +%s%N)
+PROMPT="Write a 200-word, three-paragraph essay about the history of clocks. Sentinel=$SENTINEL. Do not stop early."
+
+# ---------- A. /v1/messages stream (the path that had the bug) ----------
+A_RESP=$(mktemp)
+A_START=$(date +%s%3N)
+curl -sS -N -X POST "$PROXY_URL/v1/messages" \
+    -H "x-api-key: $MASTER_KEY" \
+    -H "anthropic-version: 2023-06-01" \
+    -H "Content-Type: application/json" \
+    -d "$(jq -n --arg p "$PROMPT" \
+        '{model: "claude-sonnet-cache", messages: [{role: "user", content: $p}], max_tokens: 400, stream: true}')" \
+    > "$A_RESP"
+A_END=$(date +%s%3N)
+A_WALL=$((A_END - A_START))
+A_BYTES=$(wc -c < "$A_RESP")
+rm -f "$A_RESP"
+
+# ---------- B. /v1/chat/completions stream (control / parity ref) ----------
+B_RESP=$(mktemp)
+B_START=$(date +%s%3N)
+curl -sS -N -X POST "$PROXY_URL/v1/chat/completions" \
+    -H "Authorization: Bearer $MASTER_KEY" \
+    -H "Content-Type: application/json" \
+    -d "$(jq -n --arg p "$PROMPT" \
+        '{model: "claude-sonnet-cache", messages: [{role: "user", content: $p}], max_tokens: 400, stream: true, stream_options: {include_usage: true}}')" \
+    > "$B_RESP"
+B_END=$(date +%s%3N)
+B_WALL=$((B_END - B_START))
+B_BYTES=$(wc -c < "$B_RESP")
+rm -f "$B_RESP"
+
+echo "A (/v1/messages):           wall=${A_WALL}ms, bytes=${A_BYTES}"
+echo "B (/v1/chat/completions):   wall=${B_WALL}ms, bytes=${B_BYTES}"
+
+if [ "$A_BYTES" -lt 500 ] || [ "$B_BYTES" -lt 500 ]; then
+    echo "FAIL: one of the streams returned <500 bytes — upstream rejected the request"
+    exit 1
+fi
+
+# Poll for both rows up to 30s — async spend logger flushes after the stream
+# completes and the anthropic_messages row tends to lag the acompletion row
+# by a few seconds.
+ROW=""
+for _ in $(seq 1 30); do
+    sleep 1
+    ROW=$(docker exec "$DB_CONTAINER" psql -U "$DB_USER" -d "$DB_NAME" -tA -F'|' -c "
+SELECT
+    call_type,
+    EXTRACT(EPOCH FROM (\"endTime\" - \"startTime\")) * 1000,
+    EXTRACT(EPOCH FROM (\"completionStartTime\" - \"startTime\")) * 1000,
+    EXTRACT(EPOCH FROM (\"endTime\" - \"completionStartTime\")) * 1000
+FROM \"LiteLLM_SpendLogs\"
+WHERE \"startTime\" > NOW() - INTERVAL '60 seconds'
+  AND call_type IN ('anthropic_messages', 'acompletion')
+ORDER BY \"startTime\" DESC
+LIMIT 2;
+")
+    # Need at least one anthropic_messages row to assert on
+    if echo "$ROW" | grep -q '^anthropic_messages'; then
+        break
+    fi
+done
+
+if [ -z "$ROW" ]; then
+    echo "FAIL: no spend_logs row found in last 20s — async logger may be backed up"
+    exit 1
+fi
+
+echo
+echo "spend_logs rows:"
+echo "$ROW" | awk -F'|' '{ printf "  %-22s duration=%6.0fms  ttft=%6.0fms  streaming=%6.0fms\n", $1, $2, $3, $4 }'
+echo
+
+A_DUR=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($2); exit}')
+A_TTFT=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($3); exit}')
+A_STREAM=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($4); exit}')
+
+B_TTFT=$(echo "$ROW" | awk -F'|' '$1=="acompletion" {print int($3); exit}')
+
+if [ -z "$A_DUR" ]; then
+    echo "FAIL: no anthropic_messages row found in last 20s"
+    exit 1
+fi
+
+FAIL=0
+
+# Assertion 1: streaming_phase must be >1s for a 200-word stream
+if [ "$A_STREAM" -lt 1000 ]; then
+    echo "FAIL [assertion 1]: streaming_phase=${A_STREAM}ms is too short."
+    echo "  Expected >1000ms for a ~200-word completion."
+    echo "  Likely cause: completion_start_time fell back to end_time"
+    echo "  (litellm_logging.py:1834-1837 fallback fires when chunk_processor"
+    echo "   never records first-chunk arrival). See bug fix in"
+    echo "   litellm/proxy/pass_through_endpoints/streaming_handler.py."
+    FAIL=1
+fi
+
+# Assertion 2: TTFT must be >300ms (real provider latency floor)
+if [ "$A_TTFT" -lt 300 ]; then
+    echo "FAIL [assertion 2]: ttft=${A_TTFT}ms is too small."
+    echo "  Expected >300ms — real Anthropic API latency is normally 1-3 seconds."
+    echo "  Likely cause: start_time passed into chunk_processor came from the"
+    echo "   streaming iterator __init__ (which runs after upstream HTTP"
+    echo "   response received), so first-chunk arrival is microseconds after."
+    echo "  See litellm_logging_obj.start_time override in chunk_processor."
+    FAIL=1
+fi
+
+# Assertion 3: TTFT must not dominate Duration
+HALF_DUR=$((A_DUR / 2))
+if [ "$A_TTFT" -gt "$HALF_DUR" ]; then
+    echo "FAIL [assertion 3]: ttft=${A_TTFT}ms > duration/2=${HALF_DUR}ms."
+    echo "  For a long-enough stream, TTFT should be a small fraction of Duration."
+    echo "  Likely cause: the same fallback as assertion 1 (TTFT collapsed to Duration)."
+    FAIL=1
+fi
+
+# Soft sanity: parity with the OpenAI transform path
+if [ -n "$B_TTFT" ] && [ "$B_TTFT" -gt 0 ]; then
+    # Use awk for float-safe ratio (ttft can vary 1.5x easily between calls)
+    RATIO=$(awk "BEGIN { printf \"%.2f\", $A_TTFT / $B_TTFT }")
+    if awk "BEGIN { exit !($A_TTFT > $B_TTFT * 3 || $B_TTFT > $A_TTFT * 3) }"; then
+        echo "WARN: TTFT parity off — anthropic_messages=${A_TTFT}ms vs acompletion=${B_TTFT}ms (ratio=${RATIO})"
+        echo "  Not a strict fail (provider cold-start variance), but worth investigating."
+    fi
+fi
+
+if [ "$FAIL" -eq 0 ]; then
+    echo "PASS: passthrough streaming TTFT is recorded correctly."
+    echo "  /v1/messages    duration=${A_DUR}ms ttft=${A_TTFT}ms streaming=${A_STREAM}ms"
+    exit 0
+else
+    exit 1
+fi
diff --git a/litellm/proxy/pass_through_endpoints/streaming_handler.py b/litellm/proxy/pass_through_endpoints/streaming_handler.py
@@ -42,6 +42,20 @@ async def chunk_processor(
         - Inject cost into chunks if include_cost_in_streaming_usage is enabled
         """
         try:
+            # Use the true request-entry timestamp held on the logging
+            # object when it's earlier than the start_time passed in. The
+            # caller's start_time is captured at the streaming-iterator
+            # constructor, which runs AFTER the upstream HTTP response
+            # has already been received — too late to represent when the
+            # client's request entered the proxy. Without this override,
+            # SpendLogs.startTime is artificially deflated by the full
+            # TTFT, making `endTime - startTime` shorter than reality.
+            true_start = getattr(litellm_logging_obj, "start_time", None)
+            if isinstance(true_start, datetime) and (
+                not isinstance(start_time, datetime) or true_start < start_time
+            ):
+                start_time = true_start
+
             raw_bytes: List[bytes] = []
             # Extract model name for cost injection
             model_name = PassThroughStreamingHandler._extract_model_for_cost_injection(
@@ -52,6 +66,16 @@ async def chunk_processor(
             )
 
             async for chunk in response.aiter_bytes():
+                # Record TTFT on the first chunk that arrives so spend_logs
+                # `completionStartTime` reflects real time-to-first-token.
+                # Without this, the fallback at
+                # litellm_logging.py:1834-1837 sets completion_start_time =
+                # end_time, making TTFT equal to total Duration for every
+                # passthrough streaming request.
+                if litellm_logging_obj.completion_start_time is None:
+                    litellm_logging_obj._update_completion_start_time(
+                        completion_start_time=datetime.now()
+                    )
                 raw_bytes.append(chunk)
                 if (
                     getattr(litellm, "include_cost_in_streaming_usage", False)