diff --git a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py index c30090d7b8b..9d45426ca95 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -299,7 +299,7 @@ def update_response_metadata( # cannot hold ``_hidden_params``: keep only the timing on the logging object (no cost # recompute) so the proxy headers and the standard logging payload can still read it. logging_obj.set_response_timing_metrics( - response_timing_metrics(start_time, end_time, logging_obj, include_overhead) + _logging_obj_timing_metrics(start_time, end_time, logging_obj, include_overhead) ) return @@ -311,5 +311,20 @@ def update_response_metadata( # the response assembled from the chunks never inherits the stream wrapper's # ``_hidden_params``, so the logging payload reads the timing from the logging object logging_obj.set_response_timing_metrics( - response_timing_metrics(start_time, end_time, logging_obj, include_overhead) + _logging_obj_timing_metrics(start_time, end_time, logging_obj, include_overhead) ) + + +def _logging_obj_timing_metrics( + start_time: datetime.datetime, + end_time: datetime.datetime, + logging_obj: LiteLLMLoggingObject, + include_overhead: bool, +) -> Mapping[str, float]: + """A stream read to completion keeps the overhead stamped when the stream was handed back.""" + timing_metrics: Final = response_timing_metrics(start_time, end_time, logging_obj, include_overhead) + stamped: Final[Mapping[str, float]] = getattr(logging_obj, "response_timing_metrics", None) or {} + stamped_overhead_ms: Final = stamped.get("litellm_overhead_time_ms") + if include_overhead or stamped_overhead_ms is None: + return timing_metrics + return {**timing_metrics, "litellm_overhead_time_ms": stamped_overhead_ms} diff --git a/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py b/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py index 5f675b03ade..4c9b4e55c76 100644 --- a/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py +++ b/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py @@ -232,6 +232,33 @@ class TestDictResultsSkipMetadataUpdate: ) assert result._hidden_params["litellm_overhead_time_ms"] == 100.0 + def test_update_response_metadata_keeps_the_handoff_overhead_when_a_stream_is_read_to_completion(self): + """A Responses API stream stamps its overhead when the stream is handed back and calls again at + stream end with include_overhead=False; that second call must not wipe the stamp.""" + result = ModelResponse() + logging_obj = MagicMock() + logging_obj.stream = True + logging_obj.response_timing_metrics = {"_response_ms": 300.0, "litellm_overhead_time_ms": 100.0} + logging_obj.model_call_details = {"llm_api_duration_ms": 200.0} + logging_obj.caching_details = None + logging_obj.response_cost_calculator = MagicMock(return_value=0.001) + logging_obj.litellm_call_id = "test-call-id" + + update_response_metadata( + result=result, + logging_obj=logging_obj, + model="gpt-4", + kwargs={}, + start_time=datetime.datetime(2025, 1, 1, 0, 0, 0), + end_time=datetime.datetime(2025, 1, 1, 0, 0, 10), + include_overhead=False, + ) + + logging_obj.set_response_timing_metrics.assert_called_once_with( + {"_response_ms": 10000.0, "litellm_overhead_time_ms": 100.0} + ) + assert "litellm_overhead_time_ms" not in result._hidden_params + def test_update_response_metadata_omits_overhead_for_completed_stream(self): """LIT-5466: the Responses streaming iterator finishes the whole stream before updating metadata, and the provider call it recorded stopped at the first byte.""" diff --git a/tests/unit/responses/test_streaming_iterator.py b/tests/unit/responses/test_streaming_iterator.py index 5072f3d3108..c63af40b0d4 100644 --- a/tests/unit/responses/test_streaming_iterator.py +++ b/tests/unit/responses/test_streaming_iterator.py @@ -730,8 +730,10 @@ def test_run_post_success_hooks_does_not_report_generation_time_as_overhead(): """LIT-5466: the provider call is timed to first byte, so at stream completion the total minus that duration is token generation, not LiteLLM overhead.""" logging_obj = _logging_obj_stub() + logging_obj.stream = True logging_obj.model_call_details = {"litellm_params": {}, "llm_api_duration_ms": 200.0} logging_obj.caching_details = None + logging_obj.response_timing_metrics = {"_response_ms": 300.0, "litellm_overhead_time_ms": 100.0} class _CompletedEvent: def __init__(self) -> None: @@ -745,6 +747,9 @@ def test_run_post_success_hooks_does_not_report_generation_time_as_overhead(): assert iterator.completed_response._hidden_params["_response_ms"] == 10000.0 assert "litellm_overhead_time_ms" not in iterator.completed_response._hidden_params + logging_obj.set_response_timing_metrics.assert_called_once_with( + {"_response_ms": 10000.0, "litellm_overhead_time_ms": 100.0} + ) def _mock_config_with_completed_response(response: ResponsesAPIResponse) -> Mock: