Log tool invocation errors

[kooshi]

Added logging for tool invocation errors

Motivation and Context

It allows me to see what's actually going wrong when a tool call fails, which may be before it ever gets to my code, like parameter name mismatches or dependency injection errors.

How Has This Been Tested?

Yes, error handling was confirmed

Breaking Changes

No

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

[halter73]

Thanks for contributing! I was almost ready to close this PR because I assumed we must already be doing this, but we are not! You're correct that an unhandled exception thrown from application code deserves an error-level log.

Currently, if you throw an exception from an [McpServerTool] method, at most you get something like this if you have trace logging enabled:

dbug: ModelContextProtocol.Server.McpServer[330297028]
      Server (AspNetCoreSseServer 1.0.0.0), Client (mcp-inspector 0.13.0) read JsonRpcRequest message from channel.
info: ModelContextProtocol.Server.McpServer[570385771]
      Server (AspNetCoreSseServer 1.0.0.0), Client (mcp-inspector 0.13.0) method 'tools/call' request handler called.
info: ModelContextProtocol.Server.McpServer[1867955179]
      Server (AspNetCoreSseServer 1.0.0.0), Client (mcp-inspector 0.13.0) method 'tools/call' request handler completed.
trce: ModelContextProtocol.Server.McpServer[1672174748]
      Server (AspNetCoreSseServer 1.0.0.0), Client (mcp-inspector 0.13.0) sending message. Message: '{"result":{"content":[{"type":"text","text":"An error occurred invoking \u0027Echo\u0027."}],"isError":true},"id":2,"jsonrpc":"2.0"}'.

So, the only indication that anything went wrong is the error result content containing "An error occurred invoking 'Echo'." in a trace-level log which most people will not even have turned on. This is a huge improvement on that, so thanks again! And I think the new logging is at the right layer where we're catching the user-unhandled exception.

It's probably worth noting, you can send your exception message to the client by throwing an McpException. The reason we don't do that for all Exceptions is partly for security and partly because the error message without context might not be helpful to the LLM on the client and serializing the entire exception with the stack trace would probably be too much. The McpException acts as an opt-in. This is a bit of a digression however, since logging and what we send to the client are completely different things.

Other than my comment about using source-generated logging and changing the log message slightly, I think we should also add a test before merging this. I wouldn't want to accidentally regress this and stop logging tool invocation errors. We don't have as much testing for our logging as I would like yet, but we do test the log output in our IdleSessionsPastMaxIdleSessionCount_ArePruned_LongestIdleFirstDespiteIdleTimeout test. You could use the MockLoggerProvider class from that test in McpServerToolTests.cs.

csharp-sdk/tests/ModelContextProtocol.AspNetCore.Tests/StreamableHttpServerConformanceTests.cs

Lines 521 to 522 in ee9b04b

	var logMessage = Assert.Single(mockLoggerProvider.LogMessages, m => m.LogLevel == LogLevel.Critical);
	Assert.StartsWith("Exceeded maximum of 2 idle sessions.", logMessage.Message);

[halter73]

Let me know if you're busy or for whatever reason would rather have us finish the PR for you. I'm happy to assist you or take it off your hands, whatever you prefer. Thanks again!

[kooshi]

Thanks for taking a look!
I'll look at making your changes.

It's probably worth noting, you can send your exception message to the client

This was actually my original intention, as the most common problem I was having was my client (VS Code) caching an old parameter name while I was developing, so the LLM would use the old one, causing a mysterious generic error.

I wanted to send the corrected parameter name back to the client, but I didn't see an easy way to pull it back out of the Microsoft.AI code.

[kooshi]

😬 my tooling mangled some whitespace, just a moment...

[kooshi]

dotnet test tests/ModelContextProtocol.Tests/ModelContextProtocol.Tests.csproj -v n --filter ToolCallError_LogsErrorMessage
Restore complete (1.1s)
  ModelContextProtocol net8.0 succeeded (2.4s) → artifacts/bin/ModelContextProtocol/net8.0/ModelContextProtocol.dll
  ModelContextProtocol net9.0 succeeded (2.5s) → artifacts/bin/ModelContextProtocol/net9.0/ModelContextProtocol.dll
  TestServerWithHosting net8.0 succeeded (0.2s) → artifacts/bin/TestServerWithHosting/net8.0/TestServerWithHosting.dll
  ModelContextProtocol.TestServer net8.0 succeeded (0.5s) → artifacts/bin/ModelContextProtocol.TestServer/net8.0/TestServer.dll
  TestServerWithHosting net9.0 succeeded (0.3s) → artifacts/bin/TestServerWithHosting/net9.0/TestServerWithHosting.dll
  ModelContextProtocol.TestServer net9.0 succeeded (0.4s) → artifacts/bin/ModelContextProtocol.TestServer/net9.0/TestServer.dll
  ModelContextProtocol.Tests net9.0 succeeded (0.8s) → artifacts/bin/ModelContextProtocol.Tests/net9.0/ModelContextProtocol.Tests.dll
  ModelContextProtocol.Tests net8.0 succeeded (0.9s) → artifacts/bin/ModelContextProtocol.Tests/net8.0/ModelContextProtocol.Tests.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v3.0.2+dd36e86129 (64-bit .NET 9.0.5)
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v3.0.2+dd36e86129 (64-bit .NET 8.0.16)
[xUnit.net 00:00:00.15]   Discovering: ModelContextProtocol.Tests
[xUnit.net 00:00:00.15]   Discovering: ModelContextProtocol.Tests
[xUnit.net 00:00:00.48]   Discovered:  ModelContextProtocol.Tests
[xUnit.net 00:00:00.49]   Discovered:  ModelContextProtocol.Tests
[xUnit.net 00:00:00.64]   Starting:    ModelContextProtocol.Tests
[xUnit.net 00:00:00.64]   Starting:    ModelContextProtocol.Tests
[xUnit.net 00:00:00.81]   Finished:    ModelContextProtocol.Tests
[xUnit.net 00:00:00.84]   Finished:    ModelContextProtocol.Tests
WARNING: Overwriting results file: /home/kooshi/source/mcp-csharp-sdk/artifacts/TestResults/ModelContextProtocol.Tests.net9.0.Unix.trx
Results File: /home/kooshi/source/mcp-csharp-sdk/artifacts/TestResults/ModelContextProtocol.Tests.net9.0.Unix.trx
  ModelContextProtocol.Tests test net9.0 succeeded (1.4s)
WARNING: Overwriting results file: /home/kooshi/source/mcp-csharp-sdk/artifacts/TestResults/ModelContextProtocol.Tests.net8.0.Unix.trx
Results File: /home/kooshi/source/mcp-csharp-sdk/artifacts/TestResults/ModelContextProtocol.Tests.net8.0.Unix.trx
  ModelContextProtocol.Tests test net8.0 succeeded (1.5s)

Test summary: total: 2, failed: 0, succeeded: 2, skipped: 0, duration: 1.5s
Build succeeded in 7.3s

Ok, we should be all set now.

[halter73]

Awesome!

[halter73]

😬 my tooling mangled some whitespace, just a moment...

I was happy to see your first commit removed some trailing whitespace. It seems like we lost that when you undid the extraneous whitespace changes. That's okay though. It's better to keep this PR focused on one thing. I'll send a PR to add the EndpointName to this log and remove the trailing whitespace in all files as a follow up.

[kooshi]

Sounds good... and explicitly removing trailing whitespace is a great idea for the tool I'm developing. I think I'll add that while I try to prevent it from wrecking leading whitespace.
Thanks for your attention and support!