Skip to content

Log MCPServer handler exceptions once, by kind - #3314

Draft
maxisbey wants to merge 1 commit into
mainfrom
mcpserver-handler-exception-logging
Draft

Log MCPServer handler exceptions once, by kind#3314
maxisbey wants to merge 1 commit into
mainfrom
mcpserver-handler-exception-logging

Conversation

@maxisbey

Copy link
Copy Markdown
Contributor

Make MCPServer log exceptions from tool, resource, and prompt handlers consistently: a crash in user code is one ERROR record with its traceback, an anticipated failure is one INFO record, 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 except ladder, and each made a different choice:

handler raises logged client sees
tool nothing is_error=True, "Error executing tool X: {e}"
static resource / template ERROR + traceback, once -32603 "Error reading resource {uri}" (message withheld)
prompt ERROR + traceback, twice (get_prompt and the dispatcher boundary) transport-dependent

The tool row is the one that hurts: _handle_call_tool converts 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 a KeyError('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.run stops erasing the exception's kind. Arguments are validated first, and a schema rejection is a plain ToolError (chained to the ValidationError, as before). Then the body runs under an except ladder: a ToolError raised deliberately (by the tool or a resolver) is re-raised as a plain ToolError; anything else is wrapped in the new UnexpectedToolError(ToolError) with __cause__ set; a nested tool's UnexpectedToolError stays one. Every arm keeps the Error executing tool X: prefix, so the result text is byte-identical. Resources get the matching UnexpectedResourceError(ResourceError), raised by whichever layer first sees the foreign exception (FunctionResource.read, FileResource.read, ResourceTemplate.create_resource, or MCPServer.read_resource for a custom Resource subclass), so __cause__ is always the original.
  • _log_handler_exception in server.py is the single logging site for tools and resources, called from _handle_call_tool / _handle_read_resource at the point the failure becomes a response. A ToolError / ResourceError that isn't one of the Unexpected* 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.
  • Prompts drop the inner logger.exception in get_prompt, so the dispatcher boundary's existing record is the only one. Giving _handle_get_prompt ownership like the other two would mean picking a wire shape, and today's prompt error shape differs by transport (legacy code=0 + str(e) vs modern -32603 "Internal server error"); that's a separate decision, already recorded by the mcpserver:prompt:unknown-name / prompts:get:missing-required-args divergences.

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.exception for every tool failure" and then walked it back over PrefectHQ/fastmcp#4036, PrefectHQ/fastmcp#4029 and PrefectHQ/fastmcp#4392 after deliberate ToolErrors 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 than DEBUG or WARNING) for the anticipated bucket is the judgement call I'd most like a second opinion on: with MCPServer's default basicConfig(INFO) it means a model's bad-argument call prints one line to stderr during local development, and a production config at WARNING hears only about crashes.

Also in here

  • ResourceError / ResourceNotFoundError raised from a static resource (a decorated fixed-URI function, or any Resource subclass's read()) now pass through — -32602 / the handler's message — as they already did from a template function and as the ResourceNotFoundError docstring and handling-errors.md promise. Previously FunctionResource.read wrapped them into a generic -32603. This is the one client-visible change, and it also shows up one level removed: a tool that does await ctx.read_resource(uri) on such a resource gets the handler's message in its is_error text instead of the generic one. Happy to split it out if preferred.
  • The SDK's own guard for a tool body that returns InputRequiredResult while its parameters use Resolve(...) now raises RuntimeError instead of ToolError, so an authoring bug is logged as a crash rather than filed as anticipated. Same result text.
  • Prompt.render chains with from exc so the boundary's traceback reaches the original.
  • Docs: new "What lands in your log" section in docs/servers/handling-errors.md (introduces ToolError as the way to say "I anticipated this", with tutorial004.py), pointers from troubleshooting.md and handlers/logging.md, and the uri-templates.md tip now recommends ResourceNotFoundError instead of "raise an exception".

Deliberately not in here

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, ToolError subclass, bad arguments (and that __cause__ is the ValidationError directly), ValidationError raised inside the body / by output-schema conversion (both crashes), unknown tool, MCPError (no MCPServer record), resolver ToolError vs resolver crash, static / template / custom-subclass resource crash, static ResourceNotFoundError, deliberate ResourceError static and template, prompt crash logged once, nested tool crash keeps its classification, and the direct call_tool() / read_resource() type and __cause__ contracts.
  • Three interaction tests run across the full transport × protocol-version matrix and assert exactly one ERROR record 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.py prove the new docs claims.
  • A wire diff of ~40 failure scenarios (in-memory legacy/auto/2026-07-28, SSE, streamable-HTTP stateful and stateless) against main: byte-identical except the static-resource pass-through above.
  • End-to-end: a small weather server run over real stdio (stderr captured as a host would) and over streamable HTTP on a socket, driven through Client; one record per failure at the expected level on both, only the three crash records left at log_level="WARNING", and the same session against main shows 0 records for the tool crash and 2 for the prompt crash.
  • ./scripts/test: 5629 passed, 100% coverage, strict-no-cover clean; 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 ResourceError and the documented Raises: contracts keep working. Softer observable differences worth knowing about:

  • Calling FunctionResource.read() / FileResource.read() directly now raises UnexpectedResourceError (a ResourceError) chained to the original, instead of a ValueError carrying the original's text.
  • MCPServer.read_resource() and get_prompt() called programmatically (outside a request) no longer write a log record themselves; the exception they raise is the record. Likewise a tool that catches ResourceError around ctx.read_resource() and recovers no longer leaves an ERROR line behind.
  • Under the in-process 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).
  • The two existing messages (Error getting resource …, Error getting prompt …) are replaced by Resource '<uri>' raised an unexpected exception on mcp.server.mcpserver.server and by the dispatcher boundary's record respectively; deliberate ResourceNotFoundErrors drop from ERROR to INFO.

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to change)
  • Documentation update

Checklist

  • I have read the MCP Documentation
  • My code follows the repository's style guidelines
  • New and existing tests pass locally
  • I have added appropriate error handling
  • I have added or updated documentation as needed

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

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.
@github-actions

Copy link
Copy Markdown
Contributor

📚 Documentation preview

Preview https://pr-3314.mcp-python-docs.pages.dev
Deployment https://174ccaa8.mcp-python-docs.pages.dev
Commit ff178c7
Triggered by @maxisbey
Updated 2026-08-16 11:50:02 UTC

raise ValueError(str(e)) from e


def _log_handler_exception(kind: Literal["Tool", "Resource"], name: str, exc: Exception) -> None:

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

remove this requirement, not needed

@@ -152,6 +154,36 @@ def boom() -> str:
)


@requirement("mcpserver:resource:read-throws:logged")

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

remove this test and requirement

@@ -119,6 +119,37 @@ def flux() -> str:
)


@requirement("mcpserver:tool:handler-throws:logged")

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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(

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

remove


## 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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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`.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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."

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

genuine question: should this use snapshot?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Log exceptions in tool calls

1 participant