From d44d281d1d873fe3bf813e931bed27a8ac3ae7ee Mon Sep 17 00:00:00 2001 From: yucheng-berri Date: Sat, 29 Aug 2026 18:11:58 -0700 Subject: [PATCH] fix(proxy): emit timing headers and overhead for /v1/messages and /v1/responses (#38840) --- litellm/litellm_core_utils/litellm_logging.py | 14 ++ .../llm_response_utils/response_metadata.py | 98 ++++++----- litellm/llms/custom_httpx/llm_http_handler.py | 2 + litellm/proxy/common_request_processing.py | 28 +++- litellm/responses/streaming_iterator.py | 2 + .../test_response_metadata.py | 154 ++++++++++++++++++ .../test_litellm_logging.py | 107 ++++++++++++ .../custom_httpx/test_llm_http_handler.py | 79 +++++++++ .../proxy/test_common_request_processing.py | 146 +++++++++++++++++ .../responses/test_streaming_iterator.py | 21 +++ 10 files changed, 609 insertions(+), 42 deletions(-) diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index c27822d0479..97c4d038734 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -547,6 +547,9 @@ class Logging(LiteLLMLoggingBaseClass): # Init Caching related details self.caching_details: CachingDetails | None = None + # Timing for results that cannot carry ``_hidden_params`` (plain-dict /v1/messages + # responses and the bridge stream wrappers); see ``update_response_metadata``. + self.response_timing_metrics: Mapping[str, float] = {} # mutable-ok: kept deep-copyable # Passthrough endpoint guardrails config for field targeting self.passthrough_guardrails_config: dict[str, Any] | None = None @@ -566,6 +569,10 @@ class Logging(LiteLLMLoggingBaseClass): self._defer_async_logging: bool = False self._enqueue_deferred_logging: Callable[[], None] | None = None + def set_response_timing_metrics(self, timing_metrics: Mapping[str, float]) -> None: + """Keep ``_response_ms`` / ``litellm_overhead_time_ms`` for a result that has no ``_hidden_params``.""" + self.response_timing_metrics = dict(timing_metrics) # mutable-ok: kept deep-copyable + def process_dynamic_callbacks(self): """ Initializes CustomLogger compatible callbacks in self.dynamic_* callbacks @@ -6005,6 +6012,13 @@ def get_standard_logging_object_payload( clean_hidden_params: Final = StandardLoggingPayloadSetup.get_hidden_params(hidden_params) if clean_hidden_params["response_cost"] is None and raw_response_cost is not None: clean_hidden_params["response_cost"] = llm_response_cost + if clean_hidden_params["litellm_overhead_time_ms"] is None and status == "success": + # /v1/messages dict results and the bridge stream wrappers keep it on the logging object; + # failure payloads stay None like every response type that carries its own _hidden_params + timing_metrics: Final = ( + getattr(logging_obj, "response_timing_metrics", None) or {} # mutable-ok: empty fallback + ) + clean_hidden_params["litellm_overhead_time_ms"] = timing_metrics.get("litellm_overhead_time_ms") model_cost_information: Final = StandardLoggingPayloadSetup.get_model_cost_information( base_model=base_model, 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 a375560288f..ac8cf438a9b 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -1,4 +1,5 @@ import datetime +from collections.abc import Mapping from typing import Any, Final from litellm.constants import LITELLM_DETAILED_TIMING @@ -13,6 +14,39 @@ from litellm.types.utils import ( ) +def response_timing_metrics( + start_time: datetime.datetime, + end_time: datetime.datetime, + logging_obj: LiteLLMLoggingObject, + include_overhead: bool = True, +) -> Mapping[str, float]: + """``_response_ms`` for the whole call, plus ``litellm_overhead_time_ms`` when it can be derived. + + On a cache hit the overhead is the total minus the cache read; otherwise it is the total minus + the provider call (``llm_api_duration_ms``). It is omitted when neither duration was recorded, + and when ``include_overhead`` is False because the two durations cover different windows. + """ + total_response_time_ms: Final = (end_time - start_time).total_seconds() * 1000 + if not include_overhead: + return {"_response_ms": total_response_time_ms} # mutable-ok: read-only timing result + caching_details: Final = logging_obj.caching_details + cache_duration_ms: Final = ( + caching_details.get("cache_duration_ms") + if caching_details is not None and caching_details.get("cache_hit") is True + else None + ) + llm_api_duration_ms: Final = logging_obj.model_call_details.get("llm_api_duration_ms") + if cache_duration_ms is not None: + overhead_ms: float | None = total_response_time_ms - cache_duration_ms + elif llm_api_duration_ms is not None: + overhead_ms = round(total_response_time_ms - llm_api_duration_ms, 4) + else: + overhead_ms = None + if overhead_ms is None: + return {"_response_ms": total_response_time_ms} + return {"_response_ms": total_response_time_ms, "litellm_overhead_time_ms": overhead_ms} + + class ResponseMetadata: """ Handles setting and managing `_hidden_params`, `response_time_ms`, and `litellm_overhead_time_ms` for LiteLLM responses @@ -52,7 +86,7 @@ class ResponseMetadata: } self._update_hidden_params(new_params) - def _update_hidden_params(self, new_params: dict) -> None: + def _update_hidden_params(self, new_params: Mapping[str, object]) -> None: """ Update hidden params - handles when self._hidden_params is a dict or HiddenParams object """ @@ -76,37 +110,24 @@ class ResponseMetadata: start_time: datetime.datetime, end_time: datetime.datetime, logging_obj: LiteLLMLoggingObject, + include_overhead: bool = True, ) -> None: """Set response timing metrics""" - total_response_time_ms: Final = (end_time - start_time).total_seconds() * 1000 + timing_metrics: Final = response_timing_metrics(start_time, end_time, logging_obj, include_overhead) + total_response_time_ms: Final = timing_metrics["_response_ms"] # Set total response time if supported if self.supports_response_time: self.result._response_ms = total_response_time_ms ######################################################### - # 1. Add _response_ms total duration + # 1. Add _response_ms total duration and the LiteLLM overhead within it + # (total minus the cache read on a cache hit, else total minus the provider call) ######################################################### - self._update_hidden_params( - { - "_response_ms": total_response_time_ms, - } - ) + self._update_hidden_params(timing_metrics) ######################################################### - # 2. Add LiteLLM overhead duration - ######################################################### - llm_api_duration_ms: Final = logging_obj.model_call_details.get("llm_api_duration_ms") - if llm_api_duration_ms is not None: - overhead_ms = round(total_response_time_ms - llm_api_duration_ms, 4) - self._update_hidden_params( - { - "litellm_overhead_time_ms": overhead_ms, - } - ) - - ######################################################### - # 3. Add callback processing duration + # 2. Add callback processing duration ######################################################### callback_duration_ms: Final = getattr(logging_obj, "callback_duration_ms", None) if callback_duration_ms is not None: @@ -117,24 +138,9 @@ class ResponseMetadata: ) ######################################################### - # 4. Add duration for reading from cache - # In this case overhead from litellm is the difference between the cache read duration and the total response time - ######################################################### - if ( - logging_obj.caching_details is not None - and logging_obj.caching_details.get("cache_hit") is True - and (cache_duration_ms := logging_obj.caching_details.get("cache_duration_ms")) is not None - ): - overhead_ms = total_response_time_ms - cache_duration_ms - self._update_hidden_params( - { - "litellm_overhead_time_ms": overhead_ms, - } - ) - - ######################################################### - # 5. Detailed per-phase timing (opt-in via env var) + # 3. Detailed per-phase timing (opt-in via env var) ######################################################### + llm_api_duration_ms: Final = logging_obj.model_call_details.get("llm_api_duration_ms") if LITELLM_DETAILED_TIMING and llm_api_duration_ms is not None: detailed: Final[dict] = { "timing_llm_api_ms": round(llm_api_duration_ms, 4), @@ -170,6 +176,7 @@ def update_response_metadata( kwargs: dict, start_time: datetime.datetime, end_time: datetime.datetime, + include_overhead: bool = True, ) -> None: """ Updates response metadata including hidden params and timing metrics @@ -177,11 +184,22 @@ def update_response_metadata( - response._hidden_params - response._hidden_params["litellm_overhead_time_ms"] - response.response_time_ms + A result that cannot hold ``_hidden_params`` gets its timing on ``logging_obj`` instead. + Callers whose ``end_time`` covers more than the recorded provider call (a stream read to + completion) pass ``include_overhead=False``, since the overhead cannot be derived there. """ - if result is None or not hasattr(result, "_hidden_params"): + if result is None: + return + if not hasattr(result, "_hidden_params"): + # /v1/messages returns a plain dict and the Anthropic / Responses bridge stream wrappers + # 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) + ) return metadata: Final = ResponseMetadata(result) metadata.set_hidden_params(logging_obj, model, kwargs) - metadata.set_timing_metrics(start_time, end_time, logging_obj) + metadata.set_timing_metrics(start_time, end_time, logging_obj, include_overhead) metadata.apply() diff --git a/litellm/llms/custom_httpx/llm_http_handler.py b/litellm/llms/custom_httpx/llm_http_handler.py index 573ba85416f..834f7d564a2 100644 --- a/litellm/llms/custom_httpx/llm_http_handler.py +++ b/litellm/llms/custom_httpx/llm_http_handler.py @@ -2872,6 +2872,7 @@ class BaseLLMHTTPHandler: headers=headers, timeout=timeout or float(response_api_optional_request_params.get("timeout", 0)), stream=stream, + logging_obj=logging_obj, **body_kwargs, ) @@ -2903,6 +2904,7 @@ class BaseLLMHTTPHandler: url=api_base, headers=headers, timeout=timeout or float(response_api_optional_request_params.get("timeout", 0)), + logging_obj=logging_obj, **body_kwargs, ) diff --git a/litellm/proxy/common_request_processing.py b/litellm/proxy/common_request_processing.py index a23669af462..c6a6639409a 100644 --- a/litellm/proxy/common_request_processing.py +++ b/litellm/proxy/common_request_processing.py @@ -1475,6 +1475,22 @@ async def _await_llm_call_cancelling_on_disconnect( monitor.cancel() +def _timing_values( + *, + hidden_params: Mapping[str, object], + logging_obj: LiteLLMLoggingObj | None, + use_logging_obj: bool, +) -> Mapping[str, object]: + """Both timing values from one source, so the two headers always describe the same window. + + /v1/messages returns a plain dict and the Anthropic / Responses bridge stream wrappers carry no + ``_hidden_params``, so ``update_response_metadata`` leaves their timing on the logging object. + """ + if hidden_params.get("_response_ms") is not None or not use_logging_obj or logging_obj is None: + return hidden_params + return getattr(logging_obj, "response_timing_metrics", None) or {} # mutable-ok: empty fallback + + class ProxyBaseLLMRequestProcessing: def __init__(self, data: dict): self.data = data @@ -1495,10 +1511,16 @@ class ProxyBaseLLMRequestProcessing: request_data: dict | None = {}, timeout: float | httpx.Timeout | None = None, litellm_logging_obj: LiteLLMLoggingObj | None = None, + read_timing_from_logging_obj: bool = True, **kwargs, ) -> dict: exclude_values: Final = {"", None, "None"} hidden_params = hidden_params or {} + timing_values: Final = _timing_values( + hidden_params=hidden_params, + logging_obj=litellm_logging_obj, + use_logging_obj=read_timing_from_logging_obj, + ) cost_breakdown: Final = _get_cost_breakdown_from_logging_obj( litellm_logging_obj=litellm_logging_obj, response_cost=response_cost @@ -1566,8 +1588,8 @@ class ProxyBaseLLMRequestProcessing: "x-litellm-key-rpm-limit": str(user_api_key_dict.rpm_limit), "x-litellm-key-max-budget": str(user_api_key_dict.max_budget), "x-litellm-key-spend": str(updated_spend), - "x-litellm-response-duration-ms": str(hidden_params.get("_response_ms", None)), - "x-litellm-overhead-duration-ms": str(hidden_params.get("litellm_overhead_time_ms", None)), + "x-litellm-response-duration-ms": str(timing_values.get("_response_ms")), + "x-litellm-overhead-duration-ms": str(timing_values.get("litellm_overhead_time_ms")), "x-litellm-callback-duration-ms": str(hidden_params.get("callback_duration_ms", None)), **( { @@ -3224,6 +3246,8 @@ class ProxyBaseLLMRequestProcessing: request_data=self.data, timeout=timeout, litellm_logging_obj=_litellm_logging_obj, + # a failed request reports no timing, matching /v1/chat/completions + read_timing_from_logging_obj=False, ) # Extract headers from exception - check both e.headers and e.response.headers headers = getattr(e, "headers", None) or {} diff --git a/litellm/responses/streaming_iterator.py b/litellm/responses/streaming_iterator.py index 368fd481e63..63adf950142 100644 --- a/litellm/responses/streaming_iterator.py +++ b/litellm/responses/streaming_iterator.py @@ -681,6 +681,8 @@ class BaseResponsesAPIStreamingIterator: kwargs=request_payload, start_time=self.start_time, end_time=end_time, + # the provider call was timed to first byte, so the whole stream minus it is not overhead + include_overhead=False, ) except Exception: # Non-blocking diff --git a/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py b/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py index 996530daa2e..a06b6bbf3cc 100644 --- a/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py +++ b/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py @@ -5,6 +5,7 @@ Covers the callback_duration_ms timing metric that flows from the Logging object through _hidden_params to the x-litellm-callback-duration-ms response header. """ +import asyncio import datetime from unittest.mock import MagicMock @@ -13,6 +14,7 @@ import litellm.proxy.common_request_processing as common_request_processing_mod from litellm.litellm_core_utils.litellm_logging import Logging from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( ResponseMetadata, + response_timing_metrics, update_response_metadata, ) from litellm.proxy._types import UserAPIKeyAuth @@ -124,6 +126,158 @@ class TestDictResultsSkipMetadataUpdate: logging_obj._response_cost_calculator.assert_not_called() assert "_hidden_params" not in anthropic_response + def test_update_response_metadata_keeps_timing_on_logging_obj_for_dict_results(self): + """LIT-5466: the /v1/messages dict cannot carry _hidden_params, so its timing + (the input to x-litellm-overhead-duration-ms and the SLP litellm_overhead_time_ms) + lands on the logging object instead - still without recomputing cost.""" + anthropic_response = {"id": "msg_123", "type": "message", "role": "assistant", "content": []} + logging_obj = MagicMock() + logging_obj.model_call_details = {"llm_api_duration_ms": 900.0} + logging_obj.caching_details = None + + update_response_metadata( + result=anthropic_response, + logging_obj=logging_obj, + model="openai/gpt-4o-mini", + kwargs={}, + start_time=datetime.datetime(2025, 1, 1, 0, 0, 0), + end_time=datetime.datetime(2025, 1, 1, 0, 0, 1), + ) + + logging_obj.set_response_timing_metrics.assert_called_once_with( + {"_response_ms": 1000.0, "litellm_overhead_time_ms": 100.0} + ) + logging_obj._response_cost_calculator.assert_not_called() + assert "_hidden_params" not in anthropic_response + + def test_update_response_metadata_keeps_timing_for_stream_wrapper_without_hidden_params(self): + """The /v1/messages bridge streams a bare async generator, which cannot hold + _hidden_params either; when the provider duration is unknown only the total is kept.""" + + async def sse_stream(): + yield b"event: message_start\n\n" + + logging_obj = MagicMock() + logging_obj.model_call_details = {} + logging_obj.caching_details = None + + async def drive(): + stream = sse_stream() + try: + update_response_metadata( + result=stream, + logging_obj=logging_obj, + model="openai/gpt-4o-mini", + kwargs={}, + start_time=datetime.datetime(2025, 1, 1, 0, 0, 0), + end_time=datetime.datetime(2025, 1, 1, 0, 0, 0, 250000), + ) + finally: + await stream.aclose() + + asyncio.run(drive()) + + logging_obj.set_response_timing_metrics.assert_called_once_with({"_response_ms": 250.0}) + logging_obj._response_cost_calculator.assert_not_called() + + def test_update_response_metadata_leaves_logging_obj_alone_for_objects_with_hidden_params(self): + """ModelResponse keeps carrying its own timing; the logging-object carrier is not written.""" + result = ModelResponse() + logging_obj = MagicMock() + logging_obj.model_call_details = {"llm_api_duration_ms": 900.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, 1), + ) + + logging_obj.set_response_timing_metrics.assert_not_called() + assert result._hidden_params["litellm_overhead_time_ms"] == 100.0 + + 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.""" + result = ModelResponse() + logging_obj = MagicMock() + 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, 1), + include_overhead=False, + ) + + assert result._hidden_params["_response_ms"] == 1000.0 + assert "litellm_overhead_time_ms" not in result._hidden_params + + +class TestResponseTimingMetrics: + """response_timing_metrics() is the single source of _response_ms / litellm_overhead_time_ms.""" + + START = datetime.datetime(2025, 1, 1, 0, 0, 0) + END = datetime.datetime(2025, 1, 1, 0, 0, 1) + + def _make_logging_obj(self, llm_api_duration_ms=None, caching_details=None): + logging_obj = MagicMock() + logging_obj.model_call_details = {} + if llm_api_duration_ms is not None: + logging_obj.model_call_details["llm_api_duration_ms"] = llm_api_duration_ms + logging_obj.caching_details = caching_details + return logging_obj + + def test_overhead_is_total_minus_provider_call(self): + logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0) + assert response_timing_metrics(self.START, self.END, logging_obj) == { + "_response_ms": 1000.0, + "litellm_overhead_time_ms": 100.0, + } + + def test_overhead_omitted_when_no_provider_or_cache_duration_recorded(self): + logging_obj = self._make_logging_obj() + assert response_timing_metrics(self.START, self.END, logging_obj) == {"_response_ms": 1000.0} + + def test_cache_hit_overhead_is_total_minus_cache_read(self): + logging_obj = self._make_logging_obj( + llm_api_duration_ms=900.0, caching_details={"cache_hit": True, "cache_duration_ms": 250.0} + ) + assert response_timing_metrics(self.START, self.END, logging_obj) == { + "_response_ms": 1000.0, + "litellm_overhead_time_ms": 750.0, + } + + def test_cache_miss_ignores_cache_duration(self): + logging_obj = self._make_logging_obj(caching_details={"cache_hit": False, "cache_duration_ms": 250.0}) + assert response_timing_metrics(self.START, self.END, logging_obj) == {"_response_ms": 1000.0} + + def test_cache_hit_without_recorded_cache_duration_falls_back_to_provider_call(self): + logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0, caching_details={"cache_hit": True}) + assert response_timing_metrics(self.START, self.END, logging_obj) == { + "_response_ms": 1000.0, + "litellm_overhead_time_ms": 100.0, + } + + def test_overhead_omitted_when_caller_measured_a_wider_window(self): + """A stream read to completion times the provider call to first byte, so the rest of the + stream is token generation, not LiteLLM overhead.""" + logging_obj = self._make_logging_obj(llm_api_duration_ms=200.0) + assert response_timing_metrics(self.START, self.END, logging_obj, include_overhead=False) == { + "_response_ms": 1000.0 + } + class TestCallbackDurationInCustomHeaders: """Test that callback_duration_ms flows into get_custom_headers.""" diff --git a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py index a45a6aaa2a3..947a55410ef 100644 --- a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py +++ b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py @@ -5994,3 +5994,110 @@ async def test_prompt_hook_injection_marker_recorded_for_every_surface(logging_o request_kwargs=untouched, ) assert "litellm_gateway_injected_cache" not in untouched["metadata"] + + +def test_get_standard_logging_object_payload_reads_overhead_from_logging_obj_for_dict_results(logging_obj): + """LIT-5466: /v1/messages returns a plain dict with no _hidden_params, so the overhead + recorded on the logging object must reach hidden_params.litellm_overhead_time_ms (SpendLogs).""" + import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + ) + + logging_obj.set_response_timing_metrics({"_response_ms": 1000.0, "litellm_overhead_time_ms": 100.0}) + now = datetime.datetime.now() + payload = get_standard_logging_object_payload( + kwargs={"litellm_call_id": "call-1", "model": "gpt-4o", "messages": []}, + init_response_obj={"id": "msg_1", "type": "message", "role": "assistant", "content": []}, + start_time=now, + end_time=now, + logging_obj=logging_obj, + status="success", + ) + + assert payload is not None + assert payload["hidden_params"]["litellm_overhead_time_ms"] == 100.0 + + +def test_get_standard_logging_object_payload_survives_logging_obj_without_timing_metrics(logging_obj): + """The payload is built inside a blanket except that returns None, so a logging object without + the timing carrier (custom subclasses, older pickles) must not silently drop every spend log.""" + import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + ) + + del logging_obj.response_timing_metrics + now = datetime.datetime.now() + payload = get_standard_logging_object_payload( + kwargs={"litellm_call_id": "call-1", "model": "gpt-4o", "messages": []}, + init_response_obj={"id": "msg_1", "type": "message", "role": "assistant", "content": []}, + start_time=now, + end_time=now, + logging_obj=logging_obj, + status="success", + ) + + assert payload is not None + assert payload["hidden_params"]["litellm_overhead_time_ms"] is None + + +def test_get_standard_logging_object_payload_failure_status_keeps_overhead_none(logging_obj): + """A post_call guardrail can fail the request after the upstream call succeeded; the failure + payload keeps litellm_overhead_time_ms None, matching responses that carry their own _hidden_params.""" + import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + ) + + logging_obj.set_response_timing_metrics({"_response_ms": 1000.0, "litellm_overhead_time_ms": 100.0}) + now = datetime.datetime.now() + payload = get_standard_logging_object_payload( + kwargs={"litellm_call_id": "call-1", "model": "gpt-4o", "messages": []}, + init_response_obj={}, + start_time=now, + end_time=now, + logging_obj=logging_obj, + status="failure", + ) + + assert payload is not None + assert payload["hidden_params"]["litellm_overhead_time_ms"] is None + + +def test_get_standard_logging_object_payload_prefers_response_hidden_params_overhead(logging_obj): + """A response that carries its own litellm_overhead_time_ms (chat completions) wins over the logging object.""" + import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + ) + + logging_obj.set_response_timing_metrics({"_response_ms": 1000.0, "litellm_overhead_time_ms": 100.0}) + response = ModelResponse() + response._hidden_params = {"litellm_overhead_time_ms": 5.0} + now = datetime.datetime.now() + payload = get_standard_logging_object_payload( + kwargs={"litellm_call_id": "call-1", "model": "gpt-4o", "messages": []}, + init_response_obj=response, + start_time=now, + end_time=now, + logging_obj=logging_obj, + status="success", + ) + + assert payload is not None + assert payload["hidden_params"]["litellm_overhead_time_ms"] == 5.0 + + +def test_response_timing_metrics_survive_deepcopy(logging_obj): + """Proxy pre-call hooks deep-copy the logging object; the timing carrier must stay copyable.""" + import copy + + assert logging_obj.response_timing_metrics == {} + logging_obj.set_response_timing_metrics({"_response_ms": 12.5}) + + assert copy.deepcopy(logging_obj).response_timing_metrics == {"_response_ms": 12.5} diff --git a/tests/test_litellm/llms/custom_httpx/test_llm_http_handler.py b/tests/test_litellm/llms/custom_httpx/test_llm_http_handler.py index b37c0f466d2..26f841c1146 100644 --- a/tests/test_litellm/llms/custom_httpx/test_llm_http_handler.py +++ b/tests/test_litellm/llms/custom_httpx/test_llm_http_handler.py @@ -271,6 +271,85 @@ async def test_async_response_api_handler_streams_when_provider_transform_adds_s assert client.post.call_args.kwargs["json"]["stream"] is True +@pytest.mark.asyncio +async def test_async_response_api_handler_streaming_passes_logging_obj_to_post(): + """LIT-5466: @track_llm_api_timing only records llm_api_duration_ms when the POST + receives logging_obj; without it streaming /v1/responses never gets + x-litellm-overhead-duration-ms (the non-streaming site is pinned by + test_async_responses_records_llm_api_duration below).""" + handler = BaseLLMHTTPHandler() + config = Mock() + config.validate_environment.return_value = {} + config.get_complete_url.return_value = "https://chatgpt.example.com/responses" + config.transform_responses_api_request.return_value = {"model": "gpt-5", "input": "hi", "stream": True} + config.sign_request.return_value = ({}, None) + client = AsyncHTTPHandler() + client.post = AsyncMock( + return_value=httpx.Response( + 200, + request=httpx.Request("POST", "https://chatgpt.example.com/responses"), + ) + ) + logging_obj = Mock() + + await handler.async_response_api_handler( + model="gpt-5", + input="hi", + responses_api_provider_config=config, + response_api_optional_request_params={}, + custom_llm_provider="chatgpt", + litellm_params=GenericLiteLLMParams(), + logging_obj=logging_obj, + client=client, + ) + + assert client.post.call_args.kwargs["logging_obj"] is logging_obj + + +@pytest.mark.asyncio +async def test_async_responses_records_llm_api_duration(): + """aresponses must feed the httpx timing into the logging obj, so the proxy can emit + x-litellm-overhead-duration-ms on /v1/responses (mirrors the arerank regression test).""" + + def handle(request: httpx.Request) -> httpx.Response: + return httpx.Response( + 200, + json={ + "id": "resp_1", + "object": "response", + "created_at": 1, + "model": "gpt-4o-mini", + "status": "completed", + "output": [ + { + "type": "message", + "id": "msg_1", + "status": "completed", + "role": "assistant", + "content": [{"type": "output_text", "text": "pong", "annotations": []}], + } + ], + "usage": {"input_tokens": 1, "output_tokens": 1, "total_tokens": 2}, + "parallel_tool_calls": True, + "tool_choice": "auto", + "tools": [], + }, + ) + + client = AsyncHTTPHandler() + client.client = httpx.AsyncClient(transport=httpx.MockTransport(handle)) + + response = await litellm.aresponses( + model="openai/gpt-4o-mini", + input="ping", + api_key="fake-key", + client=client, + ) + + assert response._hidden_params["litellm_overhead_time_ms"] is not None + assert response._hidden_params["_response_ms"] >= response._hidden_params["litellm_overhead_time_ms"] + + def test_get_agentic_loop_settings_defaults_and_overrides(): handler = BaseLLMHTTPHandler() diff --git a/tests/test_litellm/proxy/test_common_request_processing.py b/tests/test_litellm/proxy/test_common_request_processing.py index dd5049b0f28..833c3754022 100644 --- a/tests/test_litellm/proxy/test_common_request_processing.py +++ b/tests/test_litellm/proxy/test_common_request_processing.py @@ -2549,6 +2549,152 @@ class TestStreamingOverheadHeader: assert "x-litellm-overhead-duration-ms" in headers assert headers["x-litellm-overhead-duration-ms"] == "42.5" + @staticmethod + def _timing_logging_obj(timing_metrics): + from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLoggingObj + + logging_obj = LiteLLMLoggingObj( + model="openai/gpt-4o-mini", + messages=[{"role": "user", "content": "hi"}], + stream=True, + call_type="anthropic_messages", + start_time=None, + litellm_call_id="test-call-id", + function_id="test-function-id", + ) + logging_obj.set_response_timing_metrics(timing_metrics) + return logging_obj + + def test_get_custom_headers_reads_timing_from_logging_obj_when_response_has_no_hidden_params(self): + """ + LIT-5466: /v1/messages results and the bridge stream wrappers carry no + _hidden_params, so the timing headers come from the logging object. + """ + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={}, + litellm_logging_obj=self._timing_logging_obj( + {"_response_ms": 500.0, "litellm_overhead_time_ms": 42.5} + ), + ) + + assert headers["x-litellm-response-duration-ms"] == "500.0" + assert headers["x-litellm-overhead-duration-ms"] == "42.5" + + def test_get_custom_headers_skips_logging_obj_timing_on_the_failure_path(self): + """LIT-5466: a failed request reports no timing, the same as /v1/chat/completions.""" + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={}, + litellm_logging_obj=self._timing_logging_obj( + {"_response_ms": 500.0, "litellm_overhead_time_ms": 42.5} + ), + read_timing_from_logging_obj=False, + ) + + assert "x-litellm-response-duration-ms" not in headers + assert "x-litellm-overhead-duration-ms" not in headers + + def test_get_custom_headers_takes_both_timing_values_from_one_source(self): + """A response that timed itself but has no overhead (lazy provider streams) does not pick + up the logging object's overhead, which was measured over a different window.""" + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={"_response_ms": 300.0}, + litellm_logging_obj=self._timing_logging_obj( + {"_response_ms": 500.0, "litellm_overhead_time_ms": 42.5} + ), + ) + + assert headers["x-litellm-response-duration-ms"] == "300.0" + assert "x-litellm-overhead-duration-ms" not in headers + + def test_get_custom_headers_survives_a_logging_object_without_timing_metrics(self): + """Duck-typed logging objects (older custom code, test doubles) must not break headers.""" + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + class _NoTimingLoggingObj: + litellm_call_id = "test-call-id" + litellm_params = {} + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={}, + litellm_logging_obj=_NoTimingLoggingObj(), + ) + + assert "x-litellm-overhead-duration-ms" not in headers + + def test_get_custom_headers_prefers_response_hidden_params_over_logging_obj_timing(self): + """A response that carries its own timing (chat completions) is not overridden.""" + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={"_response_ms": 300.0, "litellm_overhead_time_ms": 7.5}, + litellm_logging_obj=self._timing_logging_obj( + {"_response_ms": 500.0, "litellm_overhead_time_ms": 42.5} + ), + ) + + assert headers["x-litellm-response-duration-ms"] == "300.0" + assert headers["x-litellm-overhead-duration-ms"] == "7.5" + + def test_get_custom_headers_omits_timing_when_no_source_has_it(self): + """No timing on the response and none on the logging object leaves both headers out.""" + mock_user_api_key_dict = MagicMock(spec=UserAPIKeyAuth) + mock_user_api_key_dict.tpm_limit = None + mock_user_api_key_dict.rpm_limit = None + mock_user_api_key_dict.max_budget = None + mock_user_api_key_dict.spend = 0.0 + mock_user_api_key_dict.allowed_model_region = None + + headers = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=mock_user_api_key_dict, + call_id="test-call-id", + hidden_params={}, + litellm_logging_obj=self._timing_logging_obj({}), + ) + + assert "x-litellm-response-duration-ms" not in headers + assert "x-litellm-overhead-duration-ms" not in headers + def test_get_custom_headers_omits_overhead_when_none(self): """ get_custom_headers() omits x-litellm-overhead-duration-ms diff --git a/tests/test_litellm/responses/test_streaming_iterator.py b/tests/test_litellm/responses/test_streaming_iterator.py index 38407c94fe7..677faf7f655 100644 --- a/tests/test_litellm/responses/test_streaming_iterator.py +++ b/tests/test_litellm/responses/test_streaming_iterator.py @@ -305,3 +305,24 @@ def test_stream_cache_write_completes_when_asyncio_run_closes_the_loop(monkeypat asyncio.run(_short_lived_script()) assert len(writes) == 1 + + +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.model_call_details = {"litellm_params": {}, "llm_api_duration_ms": 200.0} + logging_obj.caching_details = None + + class _CompletedEvent: + def __init__(self) -> None: + self._hidden_params: dict = {} + + iterator = _make_iterator(sse_events=[], logging_obj=logging_obj) + iterator.completed_response = _CompletedEvent() + iterator.start_time = datetime(2025, 1, 1, 0, 0, 0) + + iterator._run_post_success_hooks(datetime(2025, 1, 1, 0, 0, 10)) + + assert iterator.completed_response._hidden_params["_response_ms"] == 10000.0 + assert "litellm_overhead_time_ms" not in iterator.completed_response._hidden_params