Log MCPServer handler exceptions once, by kind - #3314
Conversation
A crashing tool used to leave no server-side trace: _handle_call_tool
turned the exception into an is_error result before the dispatcher
boundary could log it, so a KeyError('id') reached the model as "'id'"
and its traceback existed nowhere. Resources logged once and prompts
twice. Tool.run also re-wrapped a deliberate ToolError, so nothing
downstream could tell an anticipated failure from a crash.
Tool.run now validates arguments first (a schema rejection is a plain
ToolError chained to the ValidationError) and runs the body under an
except ladder that keeps the distinction in the type: a deliberate
ToolError stays a ToolError, anything else becomes the new
UnexpectedToolError. Both keep the "Error executing tool X: " text, so
results are byte-identical. Resources get the matching
UnexpectedResourceError, raised by whichever layer first sees the
foreign exception so __cause__ is always the original.
_log_handler_exception in server.py is the one place tools and
resources are logged: INFO without a traceback for ToolError and
ResourceError (deliberate, unknown name, bad arguments, not found),
ERROR with the traceback for anything else. get_prompt stops logging,
leaving the dispatcher boundary's record as the only one.
ResourceError raised from a static resource now passes through to the
client as it already did from a template.
📚 Documentation preview
|
Log at the two handler sites directly instead of through a shared helper: the tool site checks for ToolError, the resource site only has to ask whether it caught an UnexpectedResourceError. Drop the three transport-matrix logging tests and their requirement ids from the interaction suite, which is for wire behaviour; the same properties are covered next to MCPServer in test_server.py. Shorten the logging docs to a pointer, reword the handling-errors section plainly, and drop the recap bullet and prompt caveats.
![cubic-dev-ai[bot]](https://avatars.githubusercontent.com/in/1082092?s=60&v=4){kind=small}
There was a problem hiding this comment.
All reported issues were addressed across 17 files
Reply with feedback, questions, or to request a fix.
Re-trigger cubic
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Additional findings (outside current diff — PR may have been updated during review):
-
🟡
src/mcp/server/mcpserver/resources/types.py— FileResource.read (and DirectoryResource.read at line 247) now raise UnexpectedResourceError but their docstrings were not given theRaises:section that this same PR added to FunctionResource.read and ResourceTemplate.create_resource.Extended reasoning...
AGENTS.md (Code Quality) requires: "When a public API raises exceptions a caller would reasonably catch, document them in a
Raises:section." A caller reading FileResource.read's docstring ("Read the file content.") has no way to know a missing/unreadable file now surfaces as UnexpectedResourceError with the FileNotFoundError/PermissionError in cause, inconsistent with the sibling resource types updated in the same change.Verification: nit — The claim is factually true. This PR changed FileResource.read (src/mcp/server/mcpserver/resources/types.py:198-199:
raise UnexpectedResourceError(f"Error reading resource {self.uri}") from exc) and DirectoryResource.read (lines 252-253, same raise) to raise UnexpectedResourceError, but their docstrings remain "Read the file content." (line 193) and "Read the directory listing." (lin
A custom argument validator that raises something other than ValidationError escaped Tool.run unwrapped, losing the "Error executing tool" prefix and the UnexpectedToolError type. It is now wrapped as a crash, and an MCPError raised there still passes through. A ResourceError (usually ResourceNotFoundError from ctx.read_resource) that escapes a tool body is now classified like a ToolError, since it is the same anticipated outcome resources/read logs at INFO. An UnexpectedResourceError escaping a tool stays a crash. MCPServer.read_resource is now the single place a resource crash is wrapped (plus create_resource for templates), so the built-in Resource types let the original exception propagate to direct callers. Also: trimmed raise-site comments in favour of the exception docstrings, reworded the ToolError and ResourceError docstrings, documented the FunctionResource/FileResource.read change in migration.md, corrected the uri-templates tip and example, and pinned the new cases in tests (including a wire test for ResourceNotFoundError from a static resource).
…eption-logging # Conflicts: # docs_src/uri_templates/tutorial002.py
There was a problem hiding this comment.
Beyond the inline findings, this run also checked the new validation ladder from 6fd5e05 for a deliberate ToolError raised inside a custom argument validator or default_factory: pydantic propagates it raw, so it lands in the except Exception arm and is classified as a crash — but the wire result (prefix, message, is_error=True) is identical to main, so the only effect is the ERROR-vs-INFO log level for a pattern the docstrings don't sanction, and it was ruled out as a finding.
Extended reasoning...
The commits pushed since the prior review (6fd5e05 in particular) address the earlier red-flag finding at tools/base.py:151 — non-ValidationError exceptions from validators are now wrapped as UnexpectedToolError instead of escaping raw. This run's two remaining findings (a Raises-docstring inaccuracy in server.py and a dead arguments argument at the call_fn_with_arg_validation call site) are posted inline and are quality-level, not correctness blockers. The one new candidate investigated this run — a deliberate ToolError from a custom validator being reclassified as a crash — was verified against both HEAD and the base commit: the client-visible text and is_error result are byte-identical, so the difference is confined to the new log-level taxonomy for an out-of-contract raising site. The hunt exited at max_rounds, so approval is off the table regardless; this note only records what else was examined.
| UnexpectedToolError: If the tool (or a resolver) raises anything other than | ||
| `ToolError` or `MCPError`, or its return value fails output conversion. |
There was a problem hiding this comment.
🟡 nit: MCPServer.call_tool's new Raises docstring says UnexpectedToolError is raised when "the tool (or a resolver) raises anything other than ToolError or MCPError", but Tool.run's ladder (src/mcp/server/mcpserver/tools/base.py:208-210) deliberately re-raises a plain ResourceError/ResourceNotFoundError (e.g. propagated from ctx.read_resource()) as a plain anticipated ToolError, never UnexpectedToolError. The ToolError arm of the same docstring (lines 518-519) also omits this ResourceError case. Tool.run's own docstring (tools/base.py:140-144) states the contract correctly, so the two public docstrings in the same PR… [also at: src/mcp/server/mcpserver/exceptions.py:51 - nit: ToolError docstring says "A ResourceError that escapes the tool ... counts as anticipated too", but…]
Extended reasoning...
A programmatic caller of MCPServer.call_tool() whose tool lets ResourceNotFoundError from ctx.read_resource() propagate reads this Raises section (AGENTS.md requires Raises sections to document catchable exceptions accurately) and writes except UnexpectedToolError expecting to catch that case as documented, or conversely treats any non-Unexpected ToolError as covering only the three listed causes. At runtime the failure arrives as a plain ToolError (proved by this PR's own test test_resource_error_escaping_a_tool_is_anticipated asserting type(exc.value) is ToolError), so code keyed to the documented UnexpectedToolError classification silently takes the wrong branch — e.g. crash-alerting logic that re-reports UnexpectedToolError never fires, or the author adds a needless try/except inside the tool to "fix" a misclassification that never happens.
Verification: nit — the docstring is factually inaccurate about the raised type, though runtime behavior is intentional. server.py:520-521 says "UnexpectedToolError: If the tool (or a resolver) raises anything other than ToolError or MCPError", but tools/base.py:208-210 has except (ToolError, ResourceError) as exc: raise ToolError(...) from exc — a plain ResourceError/ResourceNotFoundError (a sibling of
| self.is_async, | ||
| arguments, | ||
| pass_directly or None, | ||
| pre_validated=pre_validated, | ||
| pre_validated=validated, | ||
| ) |
There was a problem hiding this comment.
🟡 After hoisting validation, Tool.run always passes pre_validated=validated to call_fn_with_arg_validation, so the raw arguments argument at this call site is dead and the helper's internal validate-fallback branch (func_metadata.py:118-120) is no longer exercised by any SDK code path — the call could simply invoke the function with the merged validated kwargs.
Extended reasoning...
Concrete cost: misleading data flow and retained duplicate logic. Before this change the fallback self.validate_arguments(arguments_to_validate) inside call_fn_with_arg_validation (src/mcp/server/mcpserver/utilities/func_metadata.py:118-120) was the live validation path for every tool without Resolve() params; now Tool.run validates up front (tools/base.py:147) and this remains the helper's only SDK call site, so a reader of tools/base.py:174-180 sees arguments passed as if it might be re-validated when it is always ignored, and the helper keeps a second validation path that only third-party callers could reach. Simpler form: merge validated | (pass_directly or {}) and dispatch to the function directly (or pass an empty dict with a comment), keeping one obvious validation site.
Verification: nit — The claim is factually true. tools/base.py:146-156 hoists validated = self.fn_metadata.validate_arguments(arguments) ahead of the body try, and line 179 unconditionally passes pre_validated=validated, so the raw arguments positional at line 177 is dead at this call site. func_metadata.py:118-120 only reads arguments_to_validate in the pre_validated is None fallback, and grep shows
1 participant
Make MCPServer log exceptions from tool, resource, and prompt handlers consistently: a crash in user code is one
ERRORrecord with its traceback, an anticipated failure is oneINFOrecord, and nothing is logged twice. What the client receives is unchanged.Fixes #3266.
Motivation and Context
Today the three primitives each hand-roll their own
exceptladder, and each made a different choice:is_error=True,"Error executing tool X: {e}"ERROR+ traceback, once-32603 "Error reading resource {uri}"(message withheld)ERROR+ traceback, twice (get_promptand the dispatcher boundary)The tool row is the one that hurts:
_handle_call_toolconverts the exception into a successful JSON-RPC response, so the dispatcher-boundary logging never sees it, and the exception object is gone by the time middleware or the OTel middleware run. For aKeyError('id')or an anyio task-group failure the result text is'id'/unhandled errors in a TaskGroup (1 sub-exception)and the traceback exists nowhere.Rather than add an eighth site-specific
logger.exception(#3267 / #3271), this makes one function own the decision and gives it enough information to make it well:Tool.runstops erasing the exception's kind. Arguments are validated first: a schema rejection is a plainToolErrorchained to theValidationErroras before, anMCPErrorfrom a validator passes through, and a validator that raises anything else is wrapped as a crash. Then the body runs under an except ladder: aToolErrororResourceErrorraised deliberately (by the tool, a resolver, or a resource it read viactx.read_resource()) is re-raised as a plainToolError, anything else is wrapped in the newUnexpectedToolError(ToolError)with__cause__set, and a nestedUnexpectedToolError/UnexpectedResourceErrorstays a crash. Every arm keeps theError executing tool X:prefix, so the result text is byte-identical. Resources get the matchingUnexpectedResourceError(ResourceError), raised inMCPServer.read_resource(andResourceTemplate.create_resource, whose message is already pinned), so__cause__is always the original._handle_call_tool/_handle_read_resourcelog at the point the failure becomes a response, and nowhere else does. AToolError/ResourceErrorthat isn't one of theUnexpected*wrappers →logger.info, no traceback, text repr-quoted so a peer-supplied name or pydantic's multi-line message stays on one physical line. Anything else →logger.exception.logger.exceptioninget_prompt, so the dispatcher boundary's existing record is the only one. Giving_handle_get_promptownership like the other two would mean picking a wire shape, and today's prompt error shape differs by transport (legacycode=0+str(e)vs modern-32603 "Internal server error"); that's a separate decision, already recorded by themcpserver:prompt:unknown-name/prompts:get:missing-required-argsdivergences.Why encode anticipated-vs-crash into the level rather than logging everything at
ERROR: level is the one filter operators get for free, and it's what Sentry/Datadog-style integrations key on. External FastMCP shipped "logger.exceptionfor every tool failure" and then walked it back over PrefectHQ/fastmcp#4036, PrefectHQ/fastmcp#4029 and PrefectHQ/fastmcp#4392 after deliberateToolErrors and model argument typos flooded error monitoring and stdio stderr. #2422 and #2346 are the same signal here. The convention across uvicorn/Flask/Django/Celery/gRPC is likewise "unexpected → ERROR with traceback, once, at the layer that swallows it; expected → lower level or nothing".INFO(rather thanDEBUGorWARNING) for the anticipated bucket is the judgement call I'd most like a second opinion on: withMCPServer's defaultbasicConfig(INFO)it means a model's bad-argument call prints one line to stderr during local development, and a production config atWARNINGhears only about crashes.Also in here
ResourceError(usuallyResourceNotFoundErrorfromctx.read_resource()) that escapes a tool body is classified as anticipated, since it is the same outcomeresources/readlogs atINFO. Same result text as before.ResourceError/ResourceNotFoundErrorraised from a static resource (a decorated fixed-URI function, or anyResourcesubclass'sread()) now pass through —-32602/ the handler's message — as they already did from a template function and as theResourceNotFoundErrordocstring andhandling-errors.mdpromise. PreviouslyFunctionResource.readwrapped them into a generic-32603. This is the one client-visible change, and it also shows up one level removed: a tool that doesawait ctx.read_resource(uri)on such a resource gets the handler's message in itsis_errortext instead of the generic one. Happy to split it out if preferred.InputRequiredResultwhile its parameters useResolve(...)now raisesRuntimeErrorinstead ofToolError, so an authoring bug is logged as a crash rather than filed as anticipated. Same result text.Prompt.renderchains withfrom excso the boundary's traceback reaches the original.docs/servers/handling-errors.md(introducesToolErroras the way to say "I anticipated this", withtutorial004.py), pointers fromtroubleshooting.mdandhandlers/logging.md, theuri-templates.mdtip and itssafe_joinexample now useResourceNotFoundError, and amigration.mdclause for theResource.read()change below.Deliberately not in here
exceptarm, but it's a wire change and a docs reversal, so it stays its own decision.Error executing tool X:prefix for a deliberateToolError(fix: prevent tool exceptions from leaking internal details to client #2198 drops it, feat(mcpserver): let ToolError carry content for is_error results #2984 keeps it).0→-32602/-32603) and prompt-side INFO classification, per above.validate_call, which fuses argument validation with the call, so there's no clean seam yet to classify it like a tool's bad arguments. Not a regression (main logged it atERRORtoo). Follow-up.MCPServer's default handler isRichHandler(rich_tracebacks=True); with no TTY (a stdio server under a host) it renders at 80 columns, so one crash record is 100+ lines of stderr. Resources and prompts already did this; tool crashes now join them. A plainer default is a separate conversation.How Has This Been Tested?
tests/server/mcpserver/test_server.py: level, message, logger name, traceback identity and wire result for each class — crash,ToolError,ToolErrorsubclass, bad arguments (and that__cause__is theValidationErrordirectly), a validator that crashes vs one that raisesMCPError,ValidationErrorraised inside the body / by output-schema conversion (both crashes), unknown tool,MCPError(no MCPServer record), resolverToolErrorvs resolver crash,ResourceNotFoundErrorvs resource crash escaping a tool viactx.read_resource(), a tool that recovers from a missing resource (nothing logged), static / template / custom-subclass resource crash, staticResourceNotFoundError, deliberateResourceErrorstatic and template, prompt crash logged once, nested tool crash keeps its classification, and the directcall_tool()/read_resource()type and__cause__contracts.ResourceNotFoundError→-32602wire behaviour across the transport matrix.tests/docs_src/test_handling_errors.py/test_troubleshooting.pyprove the new docs claims.main: byte-identical except the static-resource pass-through above.Client; one record per failure at the expected level on both, only the three crash records left atlog_level="WARNING", and the same session againstmainshows 0 records for the tool crash and 2 for the prompt crash../scripts/test: 100% coverage,strict-no-coverclean, pyright and pre-commit clean.Breaking Changes
None intended on the wire beyond the static-resource pass-through called out above. The new exception types subclass the existing ones, so
except ToolError/except ResourceErrorand the documentedRaises:contracts keep working. Softer observable differences worth knowing about:FunctionResource.read()/FileResource.read()directly now raises whatever the function or file read raised, instead of aValueErrorcarrying its text. ThroughMCPServer.read_resource()it arrives asUnexpectedResourceError(aResourceError) with the original as__cause__. Noted inmigration.md.MCPServer.read_resource()andget_prompt()called programmatically (outside a request) no longer write a log record themselves; the exception they raise is the record. Likewise a tool that catchesResourceErroraroundctx.read_resource()and recovers no longer leaves anERRORline behind.Client(mcp, raise_exceptions=True), a crashing prompt is handed to the test as the exception and not logged (tools and resources still log, since MCPServer records them before the boundary).Error getting resource …,Error getting prompt …) are replaced byResource '<uri>' raised an unexpected exceptiononmcp.server.mcpserver.serverand by the dispatcher boundary's record respectively; deliberateResourceNotFoundErrors drop fromERRORtoINFO.Types of changes
Checklist
Additional context
Supersedes #3267 and #3271 (thank you both — the diagnosis was right; this moves the fix to where all three primitives share it). Related: #698, #2153, #2198, #2422.
AI Disclaimer