From 3e23eae24896afa9de102d43ce04928ed7ecff6b Mon Sep 17 00:00:00 2001 From: "devin-ai-integration[bot]" <158243242+devin-ai-integration[bot]@users.noreply.github.com> Date: Fri, 11 Sep 2026 12:22:18 -0700 Subject: [PATCH] fix(proxy): keep call_type and request start time on failed-request spend logs (#40558) * fix(proxy): keep call_type and request start time on failed-request spend logs post_call_failure_hook pops litellm_logging_obj before the failure callbacks run, so the spend row built from request_data had a blank call_type and used datetime.now() as the start time. A guardrail-blocked MCP tool call therefore showed up in the Logs page as an LLM row with no call type and a 0s duration. Lift call_type and start_time off the logging object alongside the fields already lifted, and have the DB failure hook prefer the lifted start time. Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> * test(proxy): inject the spend writer into _ProxyDBLogger instead of patching a module global Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> --------- Co-authored-by: yucheng Co-authored-by: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> --- litellm/constants.py | 1 + .../proxy/hooks/proxy_track_cost_callback.py | 28 ++++--- .../spend_tracking/spend_tracking_utils.py | 4 +- litellm/proxy/utils.py | 9 ++- .../test_spend_tracking_utils.py | 5 ++ tests/test_litellm/proxy/test_proxy_utils.py | 76 ++++++++++++++++++- 6 files changed, 107 insertions(+), 16 deletions(-) diff --git a/litellm/constants.py b/litellm/constants.py index 028c08a691e..6b984c2673c 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -2002,6 +2002,7 @@ NON_INFERENCE_CALL_TYPES: Final[frozenset[str]] = frozenset( UNKNOWN_MODEL_SPEND_LOG_MODEL: Final[str] = "unknown-model" MAX_SPEND_LOG_MODEL_NAME_LENGTH: Final[int] = 256 +MCP_SPEND_LOG_MODEL_PREFIX: Final[str] = "MCP: " # PTU reservation rollup writes rows to LiteLLM_DailyTeamSpend with this # sentinel api_key so PTU flat cost stays distinguishable from real per-request diff --git a/litellm/proxy/hooks/proxy_track_cost_callback.py b/litellm/proxy/hooks/proxy_track_cost_callback.py index 00406ad436e..1e946cc2e23 100644 --- a/litellm/proxy/hooks/proxy_track_cost_callback.py +++ b/litellm/proxy/hooks/proxy_track_cost_callback.py @@ -1,6 +1,6 @@ import asyncio import traceback -from collections.abc import Sequence +from collections.abc import Callable, Sequence from datetime import datetime from typing import TYPE_CHECKING, Any, Final, cast @@ -23,6 +23,7 @@ from litellm.proxy.auth.auth_checks import ( ) from litellm.proxy.auth.route_checks import RouteChecks from litellm.proxy.db.db_spend_update_writer import ( + DBSpendUpdateWriter, debitable_model_access_groups, get_llm_router, ) @@ -81,6 +82,12 @@ _CAPTURED_IDENTITY_CALL_TYPES: Final[frozenset[str]] = frozenset( ) +def _proxy_spend_writer() -> DBSpendUpdateWriter: + from litellm.proxy.proxy_server import proxy_logging_obj + + return proxy_logging_obj.db_spend_update_writer + + class _ProxyDBLogger(CustomLogger): def __init__( self, @@ -88,9 +95,11 @@ class _ProxyDBLogger(CustomLogger): *, turn_off_message_logging: bool = False, message_logging: bool = True, + spend_writer: Callable[[], DBSpendUpdateWriter] = _proxy_spend_writer, ) -> None: super().__init__(turn_off_message_logging=turn_off_message_logging, message_logging=message_logging) self.spend_event_producer = spend_event_producer + self._spend_writer: Final = spend_writer async def async_log_success_event( self, kwargs: ObjectMapping, response_obj: object, start_time: datetime, end_time: datetime @@ -150,8 +159,6 @@ class _ProxyDBLogger(CustomLogger): ): return - from litellm.proxy.proxy_server import proxy_logging_obj - _metadata = dict( LiteLLMProxyRequestSetup.get_sanitized_user_information_from_key(user_api_key_dict=user_api_key_dict) ) @@ -227,13 +234,12 @@ class _ProxyDBLogger(CustomLogger): if request_data.get("litellm_trace_id") is None: request_data["litellm_trace_id"] = getattr(_litellm_logging_obj, "litellm_trace_id", None) - # Use the actual request start time from the logging object so that - # failed requests record the real duration instead of 0. - actual_start_time = datetime.now() - if _litellm_logging_obj is not None: - obj_start: Final = getattr(_litellm_logging_obj, "start_time", None) - if obj_start is not None: - actual_start_time = obj_start + lifted_start_time: Final = request_data.get("start_time") + actual_start_time: Final = ( + lifted_start_time + if isinstance(lifted_start_time, datetime) + else getattr(_litellm_logging_obj, "start_time", None) or datetime.now() + ) # A stream that broke mid-flight still billed the provider for the # chunks already delivered. ``post_call_failure_hook`` lifts that @@ -249,7 +255,7 @@ class _ProxyDBLogger(CustomLogger): existing_metadata.get("standard_logging_guardrail_information") ) - await proxy_logging_obj.db_spend_update_writer.update_database( + await self._spend_writer().update_database( token=user_api_key_dict.api_key, response_cost=recovered_response_cost, user_id=user_api_key_dict.user_id, diff --git a/litellm/proxy/spend_tracking/spend_tracking_utils.py b/litellm/proxy/spend_tracking/spend_tracking_utils.py index f0f38358cf0..01398d38687 100644 --- a/litellm/proxy/spend_tracking/spend_tracking_utils.py +++ b/litellm/proxy/spend_tracking/spend_tracking_utils.py @@ -19,6 +19,7 @@ from litellm.constants import ( LITTELM_CLI_SERVICE_ACCOUNT_NAME, LITTELM_INTERNAL_HEALTH_SERVICE_ACCOUNT_NAME, MAX_SPEND_LOG_MODEL_NAME_LENGTH, + MCP_SPEND_LOG_MODEL_PREFIX, REDACTED_BY_LITELM_STRING, SESSION_ID_OMITTED_METADATA_KEY, UNKNOWN_MODEL_SPEND_LOG_MODEL, @@ -338,7 +339,8 @@ def _sl_attribution_fallback( def _looks_like_model_name(model: str) -> bool: - return len(model) <= MAX_SPEND_LOG_MODEL_NAME_LENGTH and not any(char.isspace() for char in model) + candidate: Final = model.removeprefix(MCP_SPEND_LOG_MODEL_PREFIX) + return len(candidate) <= MAX_SPEND_LOG_MODEL_NAME_LENGTH and not any(char.isspace() for char in candidate) def get_logging_payload(kwargs, response_obj, start_time, end_time) -> SpendLogsPayload: diff --git a/litellm/proxy/utils.py b/litellm/proxy/utils.py index 253494b02f4..8e6142090a4 100644 --- a/litellm/proxy/utils.py +++ b/litellm/proxy/utils.py @@ -877,9 +877,10 @@ _EMPTY_LIFT: Final = MappingProxyType({}) def _failure_fields_to_lift(request_data: Mapping[str, object]) -> Mapping[str, object]: """Failure-path callbacks run after ``litellm_logging_obj`` is popped from request_data (it is not serialisable), so the caller merges these fields - onto request_data first: the first-handoff instant for preprocessing - latency, recovered or estimated usage for token counts, and the standard - logging object for deployment attribution on failed-request spend logs.""" + onto request_data first: the request start and first-handoff instants for + duration and preprocessing latency, the call type, recovered or estimated + usage for token counts, and the standard logging object for deployment + attribution on failed-request spend logs.""" _logging_obj: Final = request_data.get("litellm_logging_obj") if _logging_obj is None: return _EMPTY_LIFT @@ -891,7 +892,9 @@ def _failure_fields_to_lift(request_data: Mapping[str, object]) -> Mapping[str, dispatched=_first_handoff is not None, ) _entries: Final = ( + ("start_time", _model_call_details.get("start_time")), ("first_api_call_start_time", _first_handoff), + ("call_type", _model_call_details.get("call_type")), ("combined_usage_object", None if _usage_to_lift is None else _usage_to_lift[0]), ("response_cost", None if _usage_to_lift is None else (_usage_to_lift[1] or 0.0)), ("standard_logging_object", _model_call_details.get("standard_logging_object")), diff --git a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py index df113197ec6..dc8a87a97ad 100644 --- a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py +++ b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py @@ -1020,6 +1020,11 @@ _OVERLONG_MODEL: Final = "m" * (MAX_SPEND_LOG_MODEL_NAME_LENGTH + 1) ), ("gpt-5.2", ValueError("provider timed out"), "gpt-5.2"), (_BEDROCK_INFERENCE_PROFILE_ARN, ValueError("provider timed out"), _BEDROCK_INFERENCE_PROFILE_ARN), + ( + "MCP: deepwiki-ask_question", + ValueError("Content blocked: keyword 'confidential' detected"), + "MCP: deepwiki-ask_question", + ), ], ) def test_get_logging_payload_replaces_rejected_or_prompt_shaped_models_with_the_placeholder( diff --git a/tests/test_litellm/proxy/test_proxy_utils.py b/tests/test_litellm/proxy/test_proxy_utils.py index 646596c5b88..9def21c0573 100644 --- a/tests/test_litellm/proxy/test_proxy_utils.py +++ b/tests/test_litellm/proxy/test_proxy_utils.py @@ -581,6 +581,75 @@ class TestPostCallFailureHookLiftsStandardLoggingObject: assert "standard_logging_object" not in request_data +class TestPostCallFailureHookLiftsCallTypeAndStartTime: + """A guardrail-blocked MCP tool call fails before any LLM call. The failure + spend row is built from request_data after ``litellm_logging_obj`` is popped, + so ``call_type`` and the request ``start_time`` must be lifted off the logging + object first, or the Logs page shows the row as an LLM call with a blank call + type and a 0s duration (LIT-7453). + """ + + @pytest.mark.asyncio + async def test_failed_mcp_tool_call_spend_row_keeps_call_type_model_and_duration(self): + import traceback + from types import SimpleNamespace + from unittest.mock import AsyncMock + + from litellm.litellm_core_utils.litellm_logging import Logging + from litellm.proxy.hooks.proxy_track_cost_callback import _ProxyDBLogger + from litellm.proxy.spend_tracking.spend_tracking_utils import get_logging_payload + + request_start = real_datetime.datetime.now() - real_datetime.timedelta(seconds=2) + logging_obj = Logging( + model="MCP: deepwiki-ask_question", + messages=[], + stream=False, + call_type="call_mcp_tool", + start_time=request_start, + litellm_call_id="call-1", + function_id="fn-1", + ) + logging_obj.update_environment_variables( + model="MCP: deepwiki-ask_question", + user="", + optional_params={}, + litellm_params={"metadata": {"user_api_key_hash": "hashed"}}, + ) + blocked = Exception("Content blocked: keyword 'confidential' detected") + logging_obj.failure_handler(blocked, traceback.format_exc(), request_start, real_datetime.datetime.now()) + request_data = { + "name": "deepwiki-ask_question", + "arguments": {"question": "confidential"}, + "litellm_logging_obj": logging_obj, + } + proxy_logging_obj = ProxyLogging(user_api_key_cache=DualCache()) + proxy_logging_obj.alert_types = [] + spend_writer = SimpleNamespace(update_database=AsyncMock()) + original_callbacks = list(litellm.callbacks) + litellm.callbacks = [_ProxyDBLogger(spend_writer=lambda: spend_writer)] + try: + with patch.object(proxy_logging_obj, "update_request_status", new=AsyncMock()): + await proxy_logging_obj.post_call_failure_hook( + request_data=request_data, + original_exception=blocked, + user_api_key_dict=UserAPIKeyAuth(api_key="sk-test"), + ) + finally: + litellm.callbacks = original_callbacks + ProxyLogging._callback_capabilities_cache.clear() + + db_call = spend_writer.update_database.call_args.kwargs + payload = get_logging_payload( + kwargs=db_call["kwargs"], + response_obj=db_call["completion_response"], + start_time=db_call["start_time"], + end_time=db_call["end_time"], + ) + assert payload["call_type"] == "call_mcp_tool" + assert payload["model"] == "MCP: deepwiki-ask_question" + assert payload["endTime"] - payload["startTime"] >= real_datetime.timedelta(seconds=2) + + class TestPostCallFailureHookEstimatesDispatchedInputTokens: """A non-stream request that failed after dispatch (timeout, provider error) consumed provider-billed input tokens but recovered no usage. @@ -1848,13 +1917,14 @@ def test_a_failure_with_no_logging_object_lifts_nothing(): assert dict(_failure_fields_to_lift({"litellm_logging_obj": _LoggingObj({})})) == {} -def test_a_dispatched_failure_lifts_the_four_fields_the_spend_log_needs(): +def test_a_dispatched_failure_lifts_the_fields_the_spend_log_needs(): from litellm.proxy.utils import _failure_fields_to_lift lifted = _failure_fields_to_lift( { "litellm_logging_obj": _LoggingObj( { + "start_time": 1699999999.0, "first_api_call_start_time": 1700000000.0, "call_type": "acompletion", "model": FAILURE_USAGE_MODEL, @@ -1866,12 +1936,16 @@ def test_a_dispatched_failure_lifts_the_four_fields_the_spend_log_needs(): ) assert set(lifted) == { + "start_time", "first_api_call_start_time", + "call_type", "combined_usage_object", "response_cost", "standard_logging_object", } + assert lifted["start_time"] == 1699999999.0 assert lifted["first_api_call_start_time"] == 1700000000.0 + assert lifted["call_type"] == "acompletion" assert lifted["response_cost"] == 0.0 assert lifted["combined_usage_object"].prompt_tokens > 0 assert lifted["standard_logging_object"] == {"id": "log-1"}