diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index b6574a7787d..639003c9a6a 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/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 diff --git a/tests/unit/litellm_core_utils/test_litellm_logging.py b/tests/unit/litellm_core_utils/test_litellm_logging.py index 93a0b0735da..f1854563cd5 100644 --- a/tests/unit/litellm_core_utils/test_litellm_logging.py +++ b/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