diff --git a/litellm/constants.py b/litellm/constants.py index 423f01afac1..e7890c5bf09 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -144,6 +144,32 @@ MCP_HEALTH_CHECK_TIMEOUT = float(os.getenv("LITELLM_MCP_HEALTH_CHECK_TIMEOUT", " LITELLM_UI_ALLOW_HEADERS = [ "x-litellm-semantic-filter", "x-litellm-semantic-filter-tools", + # Expose LiteLLM proxy response headers to browser clients (fetch / dashboard). + # Without these, Access-Control-Expose-Headers hides them from JavaScript. + "x-litellm-call-id", + "x-litellm-model-id", + "x-litellm-cache-key", + "x-litellm-model-api-base", + "x-litellm-version", + "x-litellm-model-region", + "x-litellm-response-cost", + "x-litellm-response-cost-original", + "x-litellm-response-cost-discount-amount", + "x-litellm-response-cost-margin-amount", + "x-litellm-response-cost-margin-percent", + "x-litellm-key-tpm-limit", + "x-litellm-key-rpm-limit", + "x-litellm-key-max-budget", + "x-litellm-key-spend", + "x-litellm-response-duration-ms", + "x-litellm-overhead-duration-ms", + "x-litellm-callback-duration-ms", + "x-litellm-timing-pre-processing-ms", + "x-litellm-timing-llm-api-ms", + "x-litellm-timing-post-processing-ms", + "x-litellm-timing-message-copy-ms", + "x-litellm-fastest_response_batch_completion", + "x-litellm-timeout", ] # Gemini model-specific minimal thinking budget constants diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index 56f7f305dca..e934c0d350d 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -60,6 +60,9 @@ from litellm.integrations.deepeval.deepeval import DeepEvalLogger from litellm.integrations.mlflow import MlflowLogger from litellm.integrations.sqs import SQSLogger from litellm.litellm_core_utils.core_helpers import reconstruct_model_name +from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( + get_response_hidden_params, +) from litellm.litellm_core_utils.get_litellm_params import get_litellm_params from litellm.litellm_core_utils.llm_cost_calc.tool_call_cost_tracking import ( StandardBuiltInToolCostTracking, @@ -1693,20 +1696,31 @@ class Logging(LiteLLMLoggingBaseClass): Non-streaming success uses _process_hidden_params_and_response_cost (skipped when stream=True). Streaming assembles the full response later; without this merge, OTEL/callbacks that read metadata.hidden_params miss cost-related fields. + + Merge with any existing metadata.hidden_params (e.g. proxy-injected timing for + /v1/messages SSE) instead of replacing, so litellm_overhead_time_ms is not dropped + when the assembled response omits it. """ if logging_result is None: return - hidden_params = getattr(logging_result, "_hidden_params", None) - if not hidden_params: + incoming = get_response_hidden_params(logging_result) + if not incoming: return if self.model_call_details.get("litellm_params") is None: return self.model_call_details["litellm_params"].setdefault("metadata", {}) if self.model_call_details["litellm_params"]["metadata"] is None: self.model_call_details["litellm_params"]["metadata"] = {} - self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = getattr( - logging_result, "_hidden_params", {} - ) + md = self.model_call_details["litellm_params"]["metadata"] + if not isinstance(md, dict): + return + existing = md.get("hidden_params") + if not isinstance(existing, dict): + existing = {} + if not isinstance(incoming, dict): + md["hidden_params"] = existing or incoming + return + md["hidden_params"] = {**existing, **incoming} def _process_hidden_params_and_response_cost( self, @@ -1714,13 +1728,13 @@ class Logging(LiteLLMLoggingBaseClass): start_time, end_time, ): - hidden_params = getattr(logging_result, "_hidden_params", {}) + hidden_params = get_response_hidden_params(logging_result) if hidden_params: if self.model_call_details.get("litellm_params") is not None: self.model_call_details["litellm_params"].setdefault("metadata", {}) if self.model_call_details["litellm_params"]["metadata"] is None: self.model_call_details["litellm_params"]["metadata"] = {} - self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = getattr(logging_result, "_hidden_params", {}) # type: ignore + self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = get_response_hidden_params(logging_result) # type: ignore if self.model_call_details.get("cache_hit") is True: self.model_call_details["response_cost"] = 0.0 @@ -5299,6 +5313,13 @@ def _extract_response_obj_and_hidden_params( hidden_params = getattr(init_response_obj, "_hidden_params", None) elif isinstance(init_response_obj, dict): response_obj = init_response_obj + hp = get_response_hidden_params(init_response_obj) + if hp: + hidden_params = ( + hp if isinstance(hp, dict) else hp.model_dump(exclude_none=True) + ) + else: + hidden_params = None else: response_obj = {} @@ -5346,6 +5367,15 @@ def get_standard_logging_object_payload( litellm_params = kwargs.get("litellm_params", {}) or {} proxy_server_request = litellm_params.get("proxy_server_request") or {} + # Proxy injects timing into litellm_params.metadata.hidden_params (e.g. /v1/messages SSE) while + # _extract_response_obj_and_hidden_params only reads from the response object. Merge so + # StandardLoggingPayload.hidden_params (and spend log metadata) include litellm_overhead_time_ms. + md = litellm_params.get("metadata") + if isinstance(md, dict): + meta_hp = md.get("hidden_params") + if isinstance(meta_hp, dict) and meta_hp: + hidden_params = {**(hidden_params or {}), **meta_hp} + # Merge both litellm_metadata and metadata to get complete metadata metadata: dict = StandardLoggingPayloadSetup.merge_litellm_metadata( litellm_params 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 06933a6fbcb..ffc981448f7 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -13,6 +13,111 @@ from litellm.types.utils import ( ) +def get_response_hidden_params(response: Any) -> Union[HiddenParams, dict]: + """ + Read LiteLLM internal fields from ModelResponse/Streaming responses or from + dict-shaped provider responses (e.g. Anthropic ``/v1/messages`` JSON bodies). + + Dict responses store timing/cost under the ``_hidden_params`` key; the proxy + strips that key before returning JSON to clients. + """ + if response is None: + return {} + hp = getattr(response, "_hidden_params", None) + if hp is not None: + return hp + if isinstance(response, dict): + inner = response.get("_hidden_params") + if isinstance(inner, dict): + return inner + return {} + + +def strip_litellm_internal_keys_from_dict_response(response: Any) -> None: + """Remove internal keys from dict API responses before JSON serialization.""" + if isinstance(response, dict): + response.pop("_hidden_params", None) + + +def merge_hidden_params_with_logging_timings( + response: Any, + logging_obj: Any, + *, + end_time: Optional[datetime.datetime] = None, +) -> dict: + """ + Merge response hidden params with timing derived from the LiteLLM logging object. + + Used by the proxy when ``response`` does not expose ``_hidden_params`` (e.g. Anthropic + ``/v1/messages`` streaming async generators) or when timing keys are missing, so + ``x-litellm-overhead-duration-ms`` and spend metadata can still be populated. + + Mirrors :meth:`ResponseMetadata.set_timing_metrics` for overhead/cache/callback fields. + """ + hp_raw = get_response_hidden_params(response) + if isinstance(hp_raw, dict): + out: dict = dict(hp_raw) + elif hp_raw is not None and hasattr(hp_raw, "model_dump"): + out = hp_raw.model_dump(exclude_none=True) + else: + out = {} + + if out.get("litellm_overhead_time_ms") is not None: + return out + + if logging_obj is None or not hasattr(logging_obj, "model_call_details"): + return out + + mcd = logging_obj.model_call_details + start_time = getattr(logging_obj, "start_time", None) + _end = end_time or datetime.datetime.now() + + if start_time is None: + return out + + total_ms = (_end - start_time).total_seconds() * 1000 + out.setdefault("_response_ms", total_ms) + + llm_api_duration_ms = mcd.get("llm_api_duration_ms") + if llm_api_duration_ms is not None: + overhead_ms = round(total_ms - float(llm_api_duration_ms), 4) + out["litellm_overhead_time_ms"] = max(overhead_ms, 0.0) + else: + caching_details = getattr(logging_obj, "caching_details", None) + if ( + caching_details is not None + and caching_details.get("cache_hit") is True + and (cache_duration_ms := caching_details.get("cache_duration_ms")) + is not None + ): + out["litellm_overhead_time_ms"] = max( + total_ms - float(cache_duration_ms), 0.0 + ) + + callback_duration_ms = getattr(logging_obj, "callback_duration_ms", None) + if callback_duration_ms is not None: + out.setdefault( + "callback_duration_ms", round(float(callback_duration_ms), 4) + ) + + if LITELLM_DETAILED_TIMING and llm_api_duration_ms is not None: + detailed: dict = { + "timing_llm_api_ms": round(float(llm_api_duration_ms), 4), + } + msg_copy_ms = getattr(logging_obj, "message_copy_duration_ms", None) + if msg_copy_ms is not None: + detailed["timing_message_copy_ms"] = round(float(msg_copy_ms), 4) + api_call_start = mcd.get("api_call_start_time") + if api_call_start is not None and start_time is not None: + pre_ms = (api_call_start - start_time).total_seconds() * 1000 + detailed["timing_pre_processing_ms"] = round(pre_ms, 4) + post_ms = total_ms - pre_ms - float(llm_api_duration_ms) + detailed["timing_post_processing_ms"] = round(max(post_ms, 0), 4) + out.update(detailed) + + return out + + class ResponseMetadata: """ Handles setting and managing `_hidden_params`, `response_time_ms`, and `litellm_overhead_time_ms` for LiteLLM responses @@ -20,8 +125,8 @@ class ResponseMetadata: def __init__(self, result: Any): self.result = result - self._hidden_params: Union[HiddenParams, dict] = ( - getattr(result, "_hidden_params", {}) or {} + self._hidden_params: Union[HiddenParams, dict] = get_response_hidden_params( + result ) @property @@ -169,6 +274,15 @@ class ResponseMetadata: """Apply metadata to the response object""" if hasattr(self.result, "_hidden_params"): self.result._hidden_params = self._hidden_params + elif isinstance(self.result, dict): + # Dict-shaped responses (e.g. Anthropic Messages API) have no + # attribute slot; use a private key stripped before HTTP response. + if isinstance(self._hidden_params, dict): + self.result["_hidden_params"] = self._hidden_params + elif isinstance(self._hidden_params, HiddenParams): + self.result["_hidden_params"] = self._hidden_params.model_dump( + exclude_none=True + ) def update_response_metadata( diff --git a/litellm/proxy/common_request_processing.py b/litellm/proxy/common_request_processing.py index bad70d30da3..28e1be40e21 100644 --- a/litellm/proxy/common_request_processing.py +++ b/litellm/proxy/common_request_processing.py @@ -35,6 +35,10 @@ from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLogging from litellm.litellm_core_utils.llm_response_utils.get_headers import ( get_response_headers, ) +from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( + merge_hidden_params_with_logging_timings, + strip_litellm_internal_keys_from_dict_response, +) from litellm.litellm_core_utils.safe_json_dumps import safe_dumps from litellm.proxy._types import ProxyException, UserAPIKeyAuth from litellm.proxy.auth.auth_utils import check_response_size_is_safe @@ -417,6 +421,49 @@ class ProxyBaseLLMRequestProcessing: def __init__(self, data: dict): self.data = data + @staticmethod + def _inject_proxy_timing_into_logging_metadata( + logging_obj: Optional[LiteLLMLoggingObj], + hidden_params: dict, + ) -> None: + """ + When the response object has no _hidden_params (e.g. messages SSE), spend logs and + callbacks still read timing from litellm_params.metadata.hidden_params. + """ + if logging_obj is None or not hasattr(logging_obj, "model_call_details"): + return + timing_keys = ( + "litellm_overhead_time_ms", + "_response_ms", + "callback_duration_ms", + "timing_llm_api_ms", + "timing_pre_processing_ms", + "timing_post_processing_ms", + "timing_message_copy_ms", + ) + to_merge = { + k: hidden_params[k] + for k in timing_keys + if k in hidden_params and hidden_params[k] is not None + } + if not to_merge: + return + mcd = logging_obj.model_call_details + lp = mcd.get("litellm_params") + if not isinstance(lp, dict): + return + md = lp.get("metadata") + if md is None: + md = {} + lp["metadata"] = md + elif not isinstance(md, dict): + return + existing = md.get("hidden_params") + if existing is None: + md["hidden_params"] = to_merge + elif isinstance(existing, dict): + existing.update(to_merge) + @staticmethod def get_custom_headers( *, @@ -986,7 +1033,16 @@ class ProxyBaseLLMRequestProcessing: _exception_raised = False try: - hidden_params = getattr(response, "_hidden_params", {}) or {} + # Async generators (e.g. Anthropic /v1/messages SSE) have no _hidden_params; + # merge timing from logging_obj.model_call_details (llm_api_duration_ms, etc.). + hidden_params = merge_hidden_params_with_logging_timings( + response, + logging_obj, + end_time=datetime.now(), + ) + ProxyBaseLLMRequestProcessing._inject_proxy_timing_into_logging_metadata( + logging_obj, hidden_params + ) model_id = self._get_model_id_from_response(hidden_params, self.data) cache_key, api_base, response_cost = ( @@ -1217,9 +1273,22 @@ class ProxyBaseLLMRequestProcessing: log_context=f"litellm_call_id={logging_obj.litellm_call_id}", ) - hidden_params = ( - getattr(response, "_hidden_params", {}) or {} - ) # get any updated response headers + # Re-merge after post_call_success_hook so dict / CSW hidden_params + logging timings align. + hidden_params = merge_hidden_params_with_logging_timings( + response, + logging_obj, + end_time=datetime.now(), + ) + ProxyBaseLLMRequestProcessing._inject_proxy_timing_into_logging_metadata( + logging_obj, hidden_params + ) + model_id = self._get_model_id_from_response(hidden_params, self.data) + cache_key = hidden_params.get("cache_key", None) or "" + api_base = hidden_params.get("api_base", None) or "" + response_cost = hidden_params.get("response_cost", None) or "" + fastest_response_batch_completion = hidden_params.get( + "fastest_response_batch_completion", None + ) additional_headers = hidden_params.get("additional_headers", {}) or {} fastapi_response.headers.update( @@ -1252,6 +1321,8 @@ class ProxyBaseLLMRequestProcessing: await check_response_size_is_safe(response=response) + strip_litellm_internal_keys_from_dict_response(response) + return response async def base_passthrough_process_llm_request( 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 0a828f44fce..8cbd9a9e56e 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 @@ -6,6 +6,7 @@ through _hidden_params to the x-litellm-callback-duration-ms response header. """ import datetime +import types from unittest.mock import MagicMock import litellm.litellm_core_utils.llm_response_utils.response_metadata as response_metadata_mod @@ -13,6 +14,9 @@ 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, + get_response_hidden_params, + merge_hidden_params_with_logging_timings, + strip_litellm_internal_keys_from_dict_response, update_response_metadata, ) from litellm.proxy._types import UserAPIKeyAuth @@ -20,6 +24,77 @@ from litellm.proxy.common_request_processing import ProxyBaseLLMRequestProcessin from litellm.types.utils import ModelResponse +class TestMergeHiddenParamsWithLoggingTimings: + """Proxy merge for async generators / responses without _hidden_params.""" + + def test_fills_overhead_from_logging_obj(self): + """Simulates /v1/messages SSE: no response._hidden_params, timing on logging_obj.""" + class _FakeStream: + pass + + logging_obj = types.SimpleNamespace( + start_time=datetime.datetime(2025, 1, 1, 0, 0, 0), + model_call_details={"llm_api_duration_ms": 40.0}, + caching_details=None, + ) + + end = datetime.datetime(2025, 1, 1, 0, 0, 1) + merged = merge_hidden_params_with_logging_timings( + _FakeStream(), + logging_obj, + end_time=end, + ) + assert merged["litellm_overhead_time_ms"] == 960.0 + assert merged["_response_ms"] == 1000.0 + + def test_preserves_existing_overhead_on_response(self): + logging_obj = types.SimpleNamespace( + start_time=datetime.datetime(2025, 1, 1, 0, 0, 0), + model_call_details={"llm_api_duration_ms": 1.0}, + ) + + class R: + _hidden_params = {"litellm_overhead_time_ms": 42.0, "_response_ms": 100.0} + + merged = merge_hidden_params_with_logging_timings( + R(), + logging_obj, + end_time=datetime.datetime(2025, 1, 1, 0, 0, 1), + ) + assert merged["litellm_overhead_time_ms"] == 42.0 + + +class TestDictResponseHiddenParams: + """Dict-shaped API responses (e.g. Anthropic /v1/messages) must carry timing metadata.""" + + def test_update_response_metadata_stores_overhead_on_dict(self): + result: dict = {"id": "msg_1", "type": "message", "role": "assistant", "content": []} + logging_obj = MagicMock() + logging_obj.model_call_details = {"llm_api_duration_ms": 50.0} + logging_obj.caching_details = None + logging_obj._response_cost_calculator = MagicMock(return_value=0.0) + logging_obj.litellm_call_id = "call-1" + + start = datetime.datetime(2025, 1, 1, 0, 0, 0) + end = datetime.datetime(2025, 1, 1, 0, 0, 1) + + update_response_metadata( + result=result, + logging_obj=logging_obj, + model="claude-3-5-sonnet", + kwargs={}, + start_time=start, + end_time=end, + ) + + hidden = get_response_hidden_params(result) + assert hidden.get("litellm_overhead_time_ms") is not None + assert hidden.get("_response_ms") == 1000.0 + + strip_litellm_internal_keys_from_dict_response(result) + assert "_hidden_params" not in result + + class TestCallbackDurationMs: """Tests for the callback_duration_ms metric in ResponseMetadata.""" 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 e5fb0ebdf6e..792bbdad59a 100644 --- a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py +++ b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py @@ -2299,3 +2299,91 @@ def test_merge_hidden_params_from_response_into_metadata_no_op_when_empty(): assert "hidden_params" not in logging_obj.model_call_details["litellm_params"][ "metadata" ] + + +def test_merge_hidden_params_from_response_preserves_proxy_injected_timing(): + """Proxy may inject timing before stream end; assembled response merge must not drop it.""" + from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLoggingObj + + logging_obj = LiteLLMLoggingObj( + model="claude-3-5-sonnet", + messages=[{"role": "user", "content": "hi"}], + stream=True, + call_type="anthropic_messages", + start_time=time.time(), + litellm_call_id="merge-hp-timing", + function_id="merge-hp-timing-fn", + ) + logging_obj.model_call_details = { + "litellm_params": { + "metadata": { + "hidden_params": {"litellm_overhead_time_ms": 273.329, "_response_ms": 1590.0} + } + }, + } + + class _Assembled: + _hidden_params = {"response_cost": 0.001, "model_id": "mid-2"} + + logging_obj._merge_hidden_params_from_response_into_metadata(_Assembled()) + hp = logging_obj.model_call_details["litellm_params"]["metadata"]["hidden_params"] + assert hp["litellm_overhead_time_ms"] == 273.329 + assert hp["_response_ms"] == 1590.0 + assert hp["response_cost"] == 0.001 + assert hp["model_id"] == "mid-2" + + +def test_get_standard_logging_payload_includes_metadata_hidden_params_overhead(): + """Spend logs read overhead from standard_logging_object.hidden_params; merge metadata.hidden_params.""" + from datetime import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + Logging as LiteLLMLoggingObj, + ) + + logging_obj = LiteLLMLoggingObj( + model="claude-3-5-sonnet-20240620", + messages=[{"role": "user", "content": "hi"}], + stream=True, + call_type="anthropic_messages", + start_time=datetime.now(), + litellm_call_id="sl-overhead-meta", + function_id="sl-overhead-meta-fn", + ) + kwargs = { + "model": "claude-3-5-sonnet-20240620", + "stream": True, + "litellm_params": { + "metadata": { + "hidden_params": { + "litellm_overhead_time_ms": 88.5, + "_response_ms": 1200.0, + "model_id": "router-model-id", + } + } + }, + "response_cost": 0.0, + "custom_llm_provider": "anthropic", + } + # Dict body without _hidden_params (timing only on metadata.hidden_params) + init_response_obj = { + "id": "msg_01", + "type": "message", + "role": "assistant", + "content": [{"type": "text", "text": "ok"}], + "model": "claude-3-5-sonnet-20240620", + "usage": {"input_tokens": 1, "output_tokens": 2}, + } + now = datetime.now() + payload = get_standard_logging_object_payload( + kwargs=kwargs, + init_response_obj=init_response_obj, + 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"] == 88.5 + assert payload["hidden_params"]["model_id"] == "router-model-id"