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
|
| raise ValueError(str(e)) from e | ||
|
|
||
|
|
||
| def _log_handler_exception(kind: Literal["Tool", "Resource"], name: str, exc: Exception) -> None: |
There was a problem hiding this comment.
remove this and inline, no reason to be its own function
| @@ -141,6 +143,36 @@ def repeat(phrase: str, count: int) -> str: | |||
| assert exc_info.value.error.message.startswith("Error rendering prompt repeat: 1 validation error") | |||
|
|
|||
|
|
|||
| @requirement("mcpserver:prompt:render-throws:logged") | |||
There was a problem hiding this comment.
remove this requirement, not needed
| @@ -152,6 +154,36 @@ def boom() -> str: | |||
| ) | |||
|
|
|||
|
|
|||
| @requirement("mcpserver:resource:read-throws:logged") | |||
There was a problem hiding this comment.
remove this test and requirement
| @@ -119,6 +119,37 @@ def flux() -> str: | |||
| ) | |||
|
|
|||
|
|
|||
| @requirement("mcpserver:tool:handler-throws:logged") | |||
There was a problem hiding this comment.
removet his test and requirement. these should be elsewhere in tests not in the interaction suite
| @@ -1020,6 +1020,14 @@ def __post_init__(self) -> None: | |||
| "tool result with isError true and the failure text in content; it does not become a JSON-RPC error." | |||
| ), | |||
| ), | |||
| "mcpserver:tool:handler-throws:logged": Requirement( | |||
|
|
||
| ## What lands in your log | ||
|
|
||
| Your server keeps its own record of these failures, and it draws one more line: between a failure you anticipated and one you didn't. |
There was a problem hiding this comment.
super weird wording
|
|
||
| Resources draw the same line. The `-32603` from a crashing resource handler names only the URI, so the `ERROR` record in your log is the one place the cause and its traceback exist. `ResourceNotFoundError`, including the SDK's own `Unknown resource`, is an `INFO` line. (A template parameter that fails its type annotation, `books://{id}` read with an `id` that isn't an `int`, currently counts as a crash.) | ||
|
|
||
| Prompts aren't split yet: any failure in a prompt function, including an unknown name or a missing argument, is one `ERROR` record with its traceback, written by the transport layer that turns it into the JSON-RPC error. |
There was a problem hiding this comment.
remove this line, weird to include
| * Bad arguments are rejected against the schema before your function runs; you don't `raise` for those. | ||
| * `from mcp import MCPError`; the error-code constants come from `mcp.types`. | ||
| * In your log: an exception you didn't raise as `ToolError` is an `ERROR` record with its traceback; `ToolError`, bad tool arguments, unknown tool names, and `ResourceNotFoundError` are one `INFO` line each. | ||
| * `from mcp import MCPError`; `ToolError` and `ResourceNotFoundError` come from `mcp.server.mcpserver.exceptions`; the error-code constants come from `mcp.types`. |
There was a problem hiding this comment.
why include this line, don't. also stop with the crazy amount of semi colons. I feel like you know you're not allowed to use emdashes, so instead you use semi colons. just use other gramatical structures that are more natural please
| except ResourceError as err: | ||
| raise MCPError(code=INTERNAL_ERROR, message=str(err), data={"uri": str(params.uri)}) | ||
| _log_handler_exception("Resource", str(params.uri), err) |
There was a problem hiding this comment.
yea as I said below, inline here doing it through a tiny function is confusing
| assert record.exc_info is not None | ||
| logged = record.exc_info[1] | ||
| assert logged is not None and isinstance(logged.__cause__, ValueError) | ||
| assert str(logged.__cause__) == "No book titled 'Nothing' in the catalog." |
There was a problem hiding this comment.
genuine question: should this use snapshot?
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, and a schema rejection is a plainToolError(chained to theValidationError, as before). Then the body runs under an except ladder: aToolErrorraised deliberately (by the tool or a resolver) is re-raised as a plainToolError; anything else is wrapped in the newUnexpectedToolError(ToolError)with__cause__set; a nested tool'sUnexpectedToolErrorstays one. Every arm keeps theError executing tool X:prefix, so the result text is byte-identical. Resources get the matchingUnexpectedResourceError(ResourceError), raised by whichever layer first sees the foreign exception (FunctionResource.read,FileResource.read,ResourceTemplate.create_resource, orMCPServer.read_resourcefor a customResourcesubclass), so__cause__is always the original._log_handler_exceptioninserver.pyis the single logging site for tools and resources, called from_handle_call_tool/_handle_read_resourceat the point the failure becomes a response. 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/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, and theuri-templates.mdtip now recommendsResourceNotFoundErrorinstead of "raise an exception".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); the docs say so explicitly. 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),ValidationErrorraised inside the body / by output-schema conversion (both crashes), unknown tool,MCPError(no MCPServer record), resolverToolErrorvs resolver crash, 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.ERRORrecord chaining to the raised instance, so a dispatcher-boundary regression to double logging on any transport fails.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: 5629 passed, 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 raisesUnexpectedResourceError(aResourceError) chained to the original, instead of aValueErrorcarrying the original's text.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