scriptoriumadmin/litellm
1
0
Fork 0
mirror of https://github.com/BerriAI/litellm.git synced 2026-09-12 23:01:41 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 182

fix(proxy): keep call_type and request start time on failed-request spend logs (#40558)

Browse source 
* 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 <yucheng@berri.ai>
Co-authored-by: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>
This commit is contained in:
devin-ai-integration[bot] 2026-09-11 12:22:18 -07:00 • committed by GitHub
parent 95b438013a
commit 3e23eae248
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
6 changed files with 107 additions and 16 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
litellm/constants.py
View file

@ -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

28
litellm/proxy/hooks/proxy_track_cost_callback.py
View file

@ -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,

4
litellm/proxy/spend_tracking/spend_tracking_utils.py
View file

@ -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:

9
litellm/proxy/utils.py
View file

@ -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")),

5
tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py
View file

@ -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(

76
tests/test_litellm/proxy/test_proxy_utils.py
View file

@ -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"}