fix(logging): drop a first-token time left over from a previous attempt (#47541)

A request re-dispatched to a fallback keeps the same logging object but gets a
fresh start_time. completion_start_time was only filled when it was empty, so
an attempt that inherited a value from the earlier attempt reported a negative
TTFT. That value reaches both the spend log and the latency-based routing
cache, where one negative sample empties the buffer window and takes the whole
model group down until the cache entry expires.

Ignore a recorded first-token time that predates the attempt's start and fall
back to end_time, the value already used when none was recorded.

Co-authored-by: Claude Code <noreply@anthropic.com>
Co-authored-by: AaronHowell <111272993+AaronHowell@users.noreply.github.com>

litellm/litellm_core_utils/litellm_logging.py

@@ -3272,7 +3272,14 @@ class Logging(LiteLLMLoggingBaseClass):
                 start_time = self.start_time
             if end_time is None:
                 end_time = datetime.datetime.now()
-            if self.completion_start_time is None:
+            # A request re-dispatched to a fallback reuses this logging object but runs in
+            # its own window, so a first-token time from the previous attempt cannot belong
+            # to it. Keeping it makes the attempt report a negative TTFT.
+            first_token_seconds: Final = _timestamp_seconds(self.completion_start_time)
+            attempt_start_seconds: Final = _timestamp_seconds(start_time)
+            if first_token_seconds is None or (
+                attempt_start_seconds is not None and first_token_seconds < attempt_start_seconds
+            ):
                 self.completion_start_time = end_time
                 self.model_call_details["completion_start_time"] = self.completion_start_time
 

tests/unit/litellm_core_utils/test_litellm_logging.py

@@ -2946,6 +2946,44 @@ async def test_async_success_handler_runs_async_callbacks_in_the_post_response_p
     assert in_post_response_phase() is False, "the phase must not leak into the request task"
 
 
+@pytest.mark.parametrize("stream", [True, False], ids=["streaming", "non_streaming"])
+def test_reused_logging_obj_does_not_report_the_previous_attempts_first_token(logging_obj, stream: bool):
+    """A fallback reuses the request's logging object but runs in its own window.
+
+    When the first attempt already recorded a first-token time, the fallback must not
+    report it. Otherwise ``completion_start_time`` lands before the attempt's
+    ``start_time``, the callbacks see a negative TTFT, and latency-based routing caches
+    a negative sample that empties its buffer window.
+    """
+    logging_obj.stream = stream
+    logging_obj.model_call_details["litellm_params"] = {}
+    logging_obj.litellm_params = {}
+
+    first_attempt_start: Final = datetime.datetime(2026, 1, 1, 12, 0, 0)
+    logging_obj.update_completion_start_time(first_attempt_start + datetime.timedelta(seconds=1))
+    fallback_start: Final = first_attempt_start + datetime.timedelta(seconds=600)
+    fallback_end: Final = fallback_start + datetime.timedelta(seconds=5)
+
+    observed: dict[str, object] = {}
+
+    class Recorder(CustomLogger):
+        def log_success_event(self, kwargs, response_obj, start_time, end_time) -> None:
+            observed["completion_start_time"] = kwargs.get("completion_start_time")
+
+    with patch.object(logging_obj, "get_combined_callback_list", return_value=[Recorder()]):
+        logging_obj.success_handler(
+            result=_success_response(),
+            start_time=fallback_start,
+            end_time=fallback_end,
+        )
+
+    completion_start_time: Final = observed["completion_start_time"]
+    assert isinstance(completion_start_time, datetime.datetime)
+    assert completion_start_time >= fallback_start, (
+        "the fallback attempt reported a first-token time that predates its own start"
+    )
+
+
 def test_is_sync_litellm_request():
     assert LitellmLogging.is_sync_litellm_request({}) is True
     assert LitellmLogging.is_sync_litellm_request({"acompletion": True}) is False