fix(mcp): log MCP tool calls returning isError=true as failures (#32238)

An MCP tool call that completes with CallToolResult.isError=true correctly
returns HTTP 200 per the MCP spec, but the shared post-call logging helper
always fired async_success_handler, so the standard logging payload carried
status=success and OTel (whose _parse_error only marks ERROR on
status=failure) showed green spans for failed tools.

The helper now checks the result after async_post_mcp_tool_call_hook runs
(guardrails may flip isError there) and routes error results to the failure
path: success gates are consumed so the @client wrapper cannot enqueue a
success log, failure_handler and async_failure_handler fire with a new
MCPToolResultError carrying the tool's first text content, and
post_call_failure_hook records the failure the same way raised exceptions
already do. Raised exceptions never reach the helper, so no double failure
logging. HTTP wire behavior is unchanged

Resolves LIT-4081
This commit is contained in:
Yassin Kortam 2026-07-08 19:02:48 +03:00 • committed by GitHub
parent cd6e8cdf23
commit bfff5e8d86
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
7 changed files with 440 additions and 14 deletions

View file

@ -73,3 +73,18 @@ class MCPUpstreamAuthError(Exception):
detail=detail,
headers={"www-authenticate": challenge} if challenge else None,
)
class MCPToolResultError(Exception):
"""An MCP tool call completed with ``isError=True`` in its result.
Never raised on the wire path: streamable HTTP MCP correctly returns tool
failures as HTTP 200 with ``result.isError: true`` per the MCP spec. This
exception only drives the standard failure logging (``status="failure"``
payload, OTel ERROR span) for such results.
Lives here rather than ``utils.py`` deliberately: tests reload ``utils``
to re-read its env-derived constants, and a reload would fork this class
into two identities, breaking ``isinstance`` checks against instances
created before the reload.
"""

View file

@ -8,6 +8,7 @@ from typing import (
Dict,
List,
Literal,
Mapping,
Optional,
Set,
Tuple,
@ -78,7 +79,7 @@ if MCP_AVAILABLE:
MCPInfo,
MCPServer,
_apply_toolset_scope,
_fire_mcp_success_logging,
_fire_mcp_tool_call_logging,
_tool_name_matches,
execute_mcp_tool,
filter_tools_by_allowed_tools,
@ -86,23 +87,32 @@ if MCP_AVAILABLE:
########################################################
############ MCP Server REST API Routes #################
async def _safe_fire_mcp_success_logging(
async def _safe_fire_mcp_tool_call_logging(
logging_obj: Optional[Any],
result: Any,
start_time: datetime,
end_time: datetime,
user_api_key_auth: Optional[UserAPIKeyAuth] = None,
request_data: Optional[Mapping[str, object]] = None,
) -> None:
if logging_obj is None:
return
logging_results = await asyncio.gather(
_fire_mcp_success_logging(logging_obj, result, start_time, end_time),
_fire_mcp_tool_call_logging(
logging_obj,
result,
start_time,
end_time,
user_api_key_auth=user_api_key_auth,
request_data=request_data,
),
return_exceptions=True,
)
logging_error = logging_results[0]
if isinstance(logging_error, asyncio.CancelledError):
raise logging_error
if isinstance(logging_error, BaseException):
verbose_logger.warning("MCP tool success logging failed (continuing): %s", logging_error)
verbose_logger.warning("MCP tool call logging failed (continuing): %s", logging_error)
def _get_server_auth_header(
server,
@ -872,7 +882,14 @@ if MCP_AVAILABLE:
raw_headers=virtual_raw_headers,
litellm_logging_obj=virtual_logging_obj,
)
await _safe_fire_mcp_success_logging(virtual_logging_obj, result, _tool_start_time, datetime.now())
await _safe_fire_mcp_tool_call_logging(
virtual_logging_obj,
result,
_tool_start_time,
datetime.now(),
user_api_key_auth=user_api_key_dict,
request_data=data,
)
return result
# Validate required parameters early
@ -955,7 +972,14 @@ if MCP_AVAILABLE:
litellm_logging_obj=data.get("litellm_logging_obj"),
requested_server_id=canonical_server_id,
)
await _safe_fire_mcp_success_logging(logging_obj, result, _tool_start_time, datetime.now())
await _safe_fire_mcp_tool_call_logging(
logging_obj,
result,
_tool_start_time,
datetime.now(),
user_api_key_auth=user_api_key_dict,
request_data=data,
)
return result
except MCPMissingUserEnvVarsError as e:
verbose_logger.info(

View file

@ -20,6 +20,7 @@ from typing import (
Callable,
Dict,
List,
Mapping,
Optional,
Set,
Tuple,
@ -47,7 +48,10 @@ from litellm.proxy._experimental.mcp_server.auth.user_api_key_auth_mcp import (
from litellm.proxy._experimental.mcp_server.discoverable_endpoints import (
get_request_base_url,
)
from litellm.proxy._experimental.mcp_server.exceptions import MCPUpstreamAuthError
from litellm.proxy._experimental.mcp_server.exceptions import (
MCPToolResultError,
MCPUpstreamAuthError,
)
from litellm.proxy._experimental.mcp_server.mcp_context import (
_mcp_active_toolset_id,
_mcp_gateway_initialize_instructions,
@ -60,6 +64,7 @@ from litellm.proxy._experimental.mcp_server.utils import (
LITELLM_MCP_SERVER_VERSION,
MCPMissingUserEnvVarsError,
add_server_prefix_to_name,
extract_mcp_tool_result_error_message,
get_server_prefix,
iter_known_server_prefixes,
)
@ -2743,12 +2748,40 @@ if MCP_AVAILABLE:
return response
async def _fire_mcp_success_logging(
_MCP_CREDENTIAL_REQUEST_FIELDS = frozenset(
{
"raw_headers",
"mcp_auth_header",
"mcp_server_auth_headers",
"oauth2_headers",
"user_api_key_auth",
}
)
async def _fire_mcp_tool_call_logging(
logging_obj: LiteLLMLoggingObj,
result: Any,
start_time: datetime,
end_time: datetime,
user_api_key_auth: Optional[UserAPIKeyAuth] = None,
request_data: Optional[Mapping[str, object]] = None,
) -> None:
"""Fire post-call logging for an executed MCP tool call.
A result with ``isError=True`` is logged as a failure (``status="failure"``
payload, so OTel marks the span ERROR) while the HTTP wire behavior stays
200 + ``isError: true`` per the MCP spec. The error check runs after
``async_post_mcp_tool_call_hook`` because guardrails may flip the result
to ``isError=True`` in that hook. Raised exceptions never reach here (the
``@client`` wrapper and ``call_mcp_tool``'s except path log those), so
this cannot double-log a failure.
``request_data`` may carry credential-bearing fields (the REST path puts
``raw_headers``, ``mcp_auth_header``, ``mcp_server_auth_headers``, and
``oauth2_headers`` at the top level of its data dict), so those are
stripped before the dict is handed to ``post_call_failure_hook``
callbacks.
"""
logging_obj.post_call(original_response=result)
await logging_obj.async_post_mcp_tool_call_hook(
kwargs=logging_obj.model_call_details,
@ -2757,7 +2790,31 @@ if MCP_AVAILABLE:
end_time=end_time,
)
logging_obj.call_type = CallTypes.call_mcp_tool.value
await logging_obj.async_success_handler(result=result, start_time=start_time, end_time=end_time)
error_message = extract_mcp_tool_result_error_message(result)
if error_message is None:
await logging_obj.async_success_handler(result=result, start_time=start_time, end_time=end_time)
return
logging_obj.has_run_logging(event_type="sync_success")
logging_obj.has_run_logging(event_type="async_success")
tool_error = MCPToolResultError(error_message)
logging_obj.failure_handler(tool_error, "", start_time, end_time)
await logging_obj.async_failure_handler(tool_error, "", start_time, end_time)
if user_api_key_auth is None:
return
from litellm.proxy.proxy_server import proxy_logging_obj
if proxy_logging_obj:
sanitized_request_data = {
key: value for key, value in (request_data or {}).items() if key not in _MCP_CREDENTIAL_REQUEST_FIELDS
}
await proxy_logging_obj.post_call_failure_hook(
request_data=sanitized_request_data,
original_exception=tool_error,
user_api_key_dict=user_api_key_auth,
route="/mcp/call_tool",
)
@client
async def call_mcp_tool(
@ -2833,7 +2890,14 @@ if MCP_AVAILABLE:
raise
if litellm_logging_obj:
await _fire_mcp_success_logging(litellm_logging_obj, response, start_time, datetime.now())
await _fire_mcp_tool_call_logging(
logging_obj=litellm_logging_obj,
result=response,
start_time=start_time,
end_time=datetime.now(),
user_api_key_auth=user_api_key_auth,
request_data=kwargs,
)
return response
async def mcp_get_prompt(

View file

@ -415,6 +415,25 @@ def validate_mcp_server_name(server_name: str, raise_http_exception: bool = Fals
raise Exception(error_message)
def extract_mcp_tool_result_error_message(result: object) -> Optional[str]:
"""The first text content of an ``isError=True`` tool result, or ``None``
when the result is not an error.
Accepts both ``mcp.types.CallToolResult`` objects and their dict
equivalents, duck-typed so the ``mcp`` package is not required.
"""
is_error: object = result.get("isError") if isinstance(result, Mapping) else getattr(result, "isError", None)
if is_error is not True:
return None
content: object = result.get("content") if isinstance(result, Mapping) else getattr(result, "content", None)
if isinstance(content, (list, tuple)):
for item in content:
text: object = item.get("text") if isinstance(item, Mapping) else getattr(item, "text", None)
if isinstance(text, str) and text:
return text
return "MCP tool call returned isError=true"
TOOL_DISPLAY_NAME_PATTERN = re.compile(r"^[a-zA-Z0-9_-]+$")

View file

@ -8,8 +8,10 @@ from fastapi import HTTPException
from mcp import ReadResourceResult, Resource
from mcp.types import (
BlobResourceContents,
CallToolResult,
Prompt,
ResourceTemplate,
TextContent,
TextResourceContents,
)
@ -6598,6 +6600,308 @@ async def test_get_active_submitted_mcp_server_ids_for_user_empty_user_id_skips_
prisma_client.db.litellm_mcpservertable.find_many.assert_not_awaited()
# --------------------------------------------------------------------------- #
# MCP tool-call isError failure logging
# --------------------------------------------------------------------------- #
def _call_tool_result(is_error: bool, text: str) -> CallToolResult:
return CallToolResult(content=[TextContent(type="text", text=text)], isError=is_error)
def _mock_mcp_logging_obj() -> MagicMock:
logging_obj = MagicMock()
logging_obj.model_call_details = {}
logging_obj.async_post_mcp_tool_call_hook = AsyncMock()
logging_obj.async_success_handler = AsyncMock()
logging_obj.async_failure_handler = AsyncMock()
return logging_obj
def test_extract_mcp_tool_result_error_message():
from litellm.proxy._experimental.mcp_server.utils import (
extract_mcp_tool_result_error_message,
)
assert extract_mcp_tool_result_error_message(_call_tool_result(True, "boom")) == "boom"
assert extract_mcp_tool_result_error_message(_call_tool_result(False, "ok")) is None
assert (
extract_mcp_tool_result_error_message(CallToolResult(content=[], isError=True))
== "MCP tool call returned isError=true"
)
assert (
extract_mcp_tool_result_error_message({"isError": True, "content": [{"type": "text", "text": "denied"}]})
== "denied"
)
assert extract_mcp_tool_result_error_message({"isError": False, "content": []}) is None
assert extract_mcp_tool_result_error_message({}) is None
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_iserror_logs_failure():
"""Regression test: a CallToolResult with isError=True must go
down the failure logging path (async_failure_handler + post_call_failure_hook),
never async_success_handler."""
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
from litellm.proxy._experimental.mcp_server.exceptions import MCPToolResultError
logging_obj = _mock_mcp_logging_obj()
proxy_logging_mock = MagicMock()
proxy_logging_mock.post_call_failure_hook = AsyncMock()
user_auth = UserAPIKeyAuth(api_key="test-key", user_id="test-user")
with patch("litellm.proxy.proxy_server.proxy_logging_obj", proxy_logging_mock):
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=_call_tool_result(True, "upstream exploded"),
start_time=datetime.now(),
end_time=datetime.now(),
user_api_key_auth=user_auth,
request_data={"litellm_call_id": "cid"},
)
logging_obj.async_success_handler.assert_not_awaited()
logging_obj.failure_handler.assert_called_once()
logging_obj.async_failure_handler.assert_awaited_once()
tool_error = logging_obj.async_failure_handler.await_args.args[0]
assert isinstance(tool_error, MCPToolResultError)
assert str(tool_error) == "upstream exploded"
logging_obj.has_run_logging.assert_any_call(event_type="sync_success")
logging_obj.has_run_logging.assert_any_call(event_type="async_success")
proxy_logging_mock.post_call_failure_hook.assert_awaited_once()
hook_kwargs = proxy_logging_mock.post_call_failure_hook.await_args.kwargs
assert hook_kwargs["route"] == "/mcp/call_tool"
assert hook_kwargs["original_exception"] is tool_error
assert hook_kwargs["user_api_key_dict"] is user_auth
logging_obj.async_post_mcp_tool_call_hook.assert_awaited_once()
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_success_path_unchanged():
"""isError=False must keep today's behavior: success handler fires, no
failure logging, no post_call_failure_hook."""
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
logging_obj = _mock_mcp_logging_obj()
proxy_logging_mock = MagicMock()
proxy_logging_mock.post_call_failure_hook = AsyncMock()
result = _call_tool_result(False, "all good")
with patch("litellm.proxy.proxy_server.proxy_logging_obj", proxy_logging_mock):
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=result,
start_time=datetime.now(),
end_time=datetime.now(),
user_api_key_auth=UserAPIKeyAuth(api_key="test-key", user_id="test-user"),
request_data={},
)
logging_obj.async_success_handler.assert_awaited_once()
assert logging_obj.async_success_handler.await_args.kwargs["result"] is result
logging_obj.async_failure_handler.assert_not_awaited()
logging_obj.failure_handler.assert_not_called()
proxy_logging_mock.post_call_failure_hook.assert_not_awaited()
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_iserror_without_auth_skips_failure_hook():
"""Without a UserAPIKeyAuth the failure handlers still fire but the proxy
post_call_failure_hook (which requires one) is skipped."""
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
logging_obj = _mock_mcp_logging_obj()
proxy_logging_mock = MagicMock()
proxy_logging_mock.post_call_failure_hook = AsyncMock()
with patch("litellm.proxy.proxy_server.proxy_logging_obj", proxy_logging_mock):
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result={"isError": True, "content": [{"type": "text", "text": "denied"}]},
start_time=datetime.now(),
end_time=datetime.now(),
)
logging_obj.async_success_handler.assert_not_awaited()
logging_obj.async_failure_handler.assert_awaited_once()
assert str(logging_obj.async_failure_handler.await_args.args[0]) == "denied"
proxy_logging_mock.post_call_failure_hook.assert_not_awaited()
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_strips_credentials_from_failure_hook():
"""Credential-bearing request_data fields (raw request headers, upstream MCP
auth headers, OAuth tokens) must never reach post_call_failure_hook
callbacks; non-credential fields must survive untouched."""
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
logging_obj = _mock_mcp_logging_obj()
proxy_logging_mock = MagicMock()
proxy_logging_mock.post_call_failure_hook = AsyncMock()
user_auth = UserAPIKeyAuth(api_key="test-key", user_id="test-user")
request_data = {
"name": "explode",
"litellm_call_id": "cid",
"raw_headers": {"authorization": "Bearer sk-caller-secret"},
"mcp_auth_header": "upstream-secret",
"mcp_server_auth_headers": {"srv": {"authorization": "Bearer srv-secret"}},
"oauth2_headers": {"authorization": "Bearer oauth-secret"},
"user_api_key_auth": user_auth,
}
with patch("litellm.proxy.proxy_server.proxy_logging_obj", proxy_logging_mock):
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=_call_tool_result(True, "boom"),
start_time=datetime.now(),
end_time=datetime.now(),
user_api_key_auth=user_auth,
request_data=request_data,
)
proxy_logging_mock.post_call_failure_hook.assert_awaited_once()
hook_request_data = proxy_logging_mock.post_call_failure_hook.await_args.kwargs["request_data"]
assert hook_request_data == {"name": "explode", "litellm_call_id": "cid"}
assert "secret" not in str(hook_request_data)
def _real_mcp_logging_obj(call_id: str):
from litellm.litellm_core_utils.litellm_logging import Logging
start_time = datetime.now()
logging_obj = Logging(
model="MCP: weather/get_forecast",
messages=[{"role": "user", "content": "tool call"}],
stream=False,
call_type="call_mcp_tool",
start_time=start_time,
litellm_call_id=call_id,
function_id="test-fn",
)
logging_obj.update_environment_variables(
model="MCP: weather/get_forecast",
user="",
optional_params={},
litellm_params={"api_base": ""},
)
logging_obj.model_call_details["mcp_tool_call_metadata"] = {
"name": "get_forecast",
"arguments": {"city": "Paris"},
"mcp_server_name": "weather",
}
return logging_obj, start_time
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_iserror_builds_failure_payload(monkeypatch):
"""The standard logging payload for an isError=True result must carry
status='failure' with the tool's error text, so OTel (whose _parse_error
keys off status) marks the MCP span ERROR."""
import litellm
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
monkeypatch.setattr(litellm, "failure_callback", [])
monkeypatch.setattr(litellm, "_async_failure_callback", [])
monkeypatch.setattr(litellm, "success_callback", [])
monkeypatch.setattr(litellm, "_async_success_callback", [])
logging_obj, start_time = _real_mcp_logging_obj("test-mcp-iserror-payload")
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=_call_tool_result(True, "upstream exploded"),
start_time=start_time,
end_time=datetime.now(),
)
payload = logging_obj.model_call_details["standard_logging_object"]
assert payload["status"] == "failure"
assert payload["error_str"] == "upstream exploded"
assert payload["error_information"]["error_class"] == "MCPToolResultError"
assert payload["metadata"]["mcp_tool_call_metadata"]["name"] == "get_forecast"
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_success_builds_success_payload(monkeypatch):
"""isError=False still produces a status='success' payload."""
import litellm
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
monkeypatch.setattr(litellm, "failure_callback", [])
monkeypatch.setattr(litellm, "_async_failure_callback", [])
monkeypatch.setattr(litellm, "success_callback", [])
monkeypatch.setattr(litellm, "_async_success_callback", [])
logging_obj, start_time = _real_mcp_logging_obj("test-mcp-success-payload")
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=_call_tool_result(False, "all good"),
start_time=start_time,
end_time=datetime.now(),
)
payload = logging_obj.model_call_details["standard_logging_object"]
assert payload["status"] == "success"
@pytest.mark.asyncio
async def test_fire_mcp_tool_call_logging_iserror_emits_otel_error_span(monkeypatch):
"""End-to-end regression for the OTel symptom: an isError=True tool
result must reach OTel as an MCP span with StatusCode.ERROR and the tool's
error message, while isError=False stays non-error."""
pytest.importorskip("opentelemetry")
from opentelemetry.sdk.trace.export.in_memory_span_exporter import (
InMemorySpanExporter,
)
from opentelemetry.trace.status import StatusCode
import litellm
from litellm.integrations.otel import OpenTelemetryV2Config
from litellm.integrations.otel.logger import OpenTelemetryV2
from litellm.integrations.otel.plumbing import providers
from litellm.proxy._experimental.mcp_server.server import (
_fire_mcp_tool_call_logging,
)
cfg = OpenTelemetryV2Config(exporter="in_memory", legacy_compat=False)
exporter = InMemorySpanExporter()
tracer_provider = providers.build_tracer_provider(cfg, exporter=exporter)
otel_logger = OpenTelemetryV2(config=cfg, tracer_provider=tracer_provider)
monkeypatch.setattr(litellm, "failure_callback", [])
monkeypatch.setattr(litellm, "_async_failure_callback", [otel_logger])
monkeypatch.setattr(litellm, "success_callback", [])
monkeypatch.setattr(litellm, "_async_success_callback", [otel_logger])
logging_obj, start_time = _real_mcp_logging_obj("test-mcp-iserror-otel")
await _fire_mcp_tool_call_logging(
logging_obj=logging_obj,
result=_call_tool_result(True, "upstream exploded"),
start_time=start_time,
end_time=datetime.now(),
)
(span,) = exporter.get_finished_spans()
assert span.name == "tools/call get_forecast"
assert span.status.status_code is StatusCode.ERROR
assert span.attributes["error.type"] == "MCPToolResultError"
assert "upstream exploded" in (span.status.description or "")
@pytest.mark.asyncio
async def test_call_tool_with_legacy_db_m2m_server_resolves_oauth2_flow():
"""

View file

@ -433,7 +433,7 @@ class TestCallToolRestApiVirtualTools:
return_value=fake_result,
) as mock_execute,
patch(
"litellm.proxy._experimental.mcp_server.rest_endpoints._fire_mcp_success_logging",
"litellm.proxy._experimental.mcp_server.rest_endpoints._fire_mcp_tool_call_logging",
new_callable=AsyncMock,
side_effect=RuntimeError("logging failed"),
) as mock_fire_logging,

View file

@ -1559,7 +1559,7 @@ class TestCallToolRestAPI:
fire_logging = AsyncMock(side_effect=RuntimeError("logging failed"))
monkeypatch.setattr(
rest_endpoints,
"_fire_mcp_success_logging",
"_fire_mcp_tool_call_logging",
fire_logging,
raising=False,
)
@ -1590,13 +1590,13 @@ class TestCallToolRestAPI:
fire_logging = AsyncMock(side_effect=asyncio.CancelledError())
monkeypatch.setattr(
rest_endpoints,
"_fire_mcp_success_logging",
"_fire_mcp_tool_call_logging",
fire_logging,
raising=False,
)
with pytest.raises(asyncio.CancelledError):
await rest_endpoints._safe_fire_mcp_success_logging(
await rest_endpoints._safe_fire_mcp_tool_call_logging(
object(), {"result": "ok"}, datetime.now(), datetime.now()
)