Skip to content

Commit 53e9ed8

Browse files
CopilotCopilot
authored
Log tool call name on success, not just failure (#1256)
1 parent dbf91bc commit 53e9ed8

File tree

5 files changed

+443
-22
lines changed

5 files changed

+443
-22
lines changed

‎src/ModelContextProtocol.Core/Server/McpServerImpl.cs‎

Lines changed: 60 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -392,7 +392,17 @@ await originalListResourceTemplatesHandler(request, cancellationToken).Configure
392392
}
393393
}
394394

395-
return await handler(request, cancellationToken).ConfigureAwait(false);
395+
try
396+
{
397+
var result = await handler(request, cancellationToken).ConfigureAwait(false);
398+
ReadResourceCompleted(request.Params?.Uri ?? string.Empty);
399+
return result;
400+
}
401+
catch (Exception e)
402+
{
403+
ReadResourceError(request.Params?.Uri ?? string.Empty, e);
404+
throw;
405+
}
396406
});
397407
subscribeHandler = BuildFilterPipeline(subscribeHandler, options.Filters.SubscribeToResourcesFilters);
398408
unsubscribeHandler = BuildFilterPipeline(unsubscribeHandler, options.Filters.UnsubscribeFromResourcesFilters);
@@ -487,7 +497,7 @@ await originalListPromptsHandler(request, cancellationToken).ConfigureAwait(fals
487497

488498
listPromptsHandler = BuildFilterPipeline(listPromptsHandler, options.Filters.ListPromptsFilters);
489499
getPromptHandler = BuildFilterPipeline(getPromptHandler, options.Filters.GetPromptFilters, handler =>
490-
(request, cancellationToken) =>
500+
async (request, cancellationToken) =>
491501
{
492502
// Initial handler that sets MatchedPrimitive
493503
if (request.Params?.Name is { } promptName && prompts is not null &&
@@ -496,7 +506,17 @@ await originalListPromptsHandler(request, cancellationToken).ConfigureAwait(fals
496506
request.MatchedPrimitive = prompt;
497507
}
498508

499-
return handler(request, cancellationToken);
509+
try
510+
{
511+
var result = await handler(request, cancellationToken).ConfigureAwait(false);
512+
GetPromptCompleted(request.Params?.Name ?? string.Empty);
513+
return result;
514+
}
515+
catch (Exception e)
516+
{
517+
GetPromptError(request.Params?.Name ?? string.Empty, e);
518+
throw;
519+
}
500520
});
501521

502522
ServerCapabilities.Prompts.ListChanged = listChanged;
@@ -610,20 +630,35 @@ await originalListToolsHandler(request, cancellationToken).ConfigureAwait(false)
610630

611631
try
612632
{
613-
return await handler(request, cancellationToken).ConfigureAwait(false);
633+
var result = await handler(request, cancellationToken).ConfigureAwait(false);
634+
635+
// Don't log here for task-augmented calls; logging happens asynchronously
636+
// in ExecuteToolAsTaskAsync when the tool actually completes.
637+
if (result.Task is null)
638+
{
639+
ToolCallCompleted(request.Params?.Name ?? string.Empty, result.IsError is true);
640+
}
641+
642+
return result;
614643
}
615-
catch (Exception e) when (e is not OperationCanceledException and not McpProtocolException)
644+
catch (Exception e)
616645
{
617646
ToolCallError(request.Params?.Name ?? string.Empty, e);
618647

619-
string errorMessage = e is McpException ?
620-
$"An error occurred invoking '{request.Params?.Name}': {e.Message}" :
621-
$"An error occurred invoking '{request.Params?.Name}'.";
648+
if ((e is OperationCanceledException && cancellationToken.IsCancellationRequested) || e is McpProtocolException)
649+
{
650+
throw;
651+
}
622652

623653
return new()
624654
{
625655
IsError = true,
626-
Content = [new TextContentBlock { Text = errorMessage }],
656+
Content = [new TextContentBlock
657+
{
658+
Text = e is McpException ?
659+
$"An error occurred invoking '{request.Params?.Name}': {e.Message}" :
660+
$"An error occurred invoking '{request.Params?.Name}'.",
661+
}],
627662
};
628663
}
629664
});
@@ -944,6 +979,21 @@ internal static LoggingLevel ToLoggingLevel(LogLevel level) =>
944979
[LoggerMessage(Level = LogLevel.Error, Message = "\"{ToolName}\" threw an unhandled exception.")]
945980
private partial void ToolCallError(string toolName, Exception exception);
946981

982+
[LoggerMessage(Level = LogLevel.Information, Message = "\"{ToolName}\" completed. IsError = {IsError}.")]
983+
private partial void ToolCallCompleted(string toolName, bool isError);
984+
985+
[LoggerMessage(Level = LogLevel.Error, Message = "GetPrompt \"{PromptName}\" threw an unhandled exception.")]
986+
private partial void GetPromptError(string promptName, Exception exception);
987+
988+
[LoggerMessage(Level = LogLevel.Information, Message = "GetPrompt \"{PromptName}\" completed.")]
989+
private partial void GetPromptCompleted(string promptName);
990+
991+
[LoggerMessage(Level = LogLevel.Error, Message = "ReadResource \"{ResourceUri}\" threw an unhandled exception.")]
992+
private partial void ReadResourceError(string resourceUri, Exception exception);
993+
994+
[LoggerMessage(Level = LogLevel.Information, Message = "ReadResource \"{ResourceUri}\" completed.")]
995+
private partial void ReadResourceCompleted(string resourceUri);
996+
947997
/// <summary>
948998
/// Executes a tool call as a task and returns a CallToolTaskResult immediately.
949999
/// </summary>
@@ -1004,6 +1054,7 @@ private async ValueTask<CallToolResult> ExecuteToolAsTaskAsync(
10041054

10051055
// Invoke the tool with task-specific cancellation token
10061056
var result = await tool.InvokeAsync(request, taskCancellationToken).ConfigureAwait(false);
1057+
ToolCallCompleted(request.Params?.Name ?? string.Empty, result.IsError is true);
10071058

10081059
// Determine final status based on whether there was an error
10091060
var finalStatus = result.IsError is true ? McpTaskStatus.Failed : McpTaskStatus.Completed;

‎tests/ModelContextProtocol.Tests/Configuration/McpServerBuilderExtensionsPromptsTests.cs‎

Lines changed: 82 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
using Microsoft.Extensions.AI;
22
using Microsoft.Extensions.DependencyInjection;
3+
using Microsoft.Extensions.Logging;
34
using Microsoft.Extensions.Options;
45
using ModelContextProtocol.Client;
56
using ModelContextProtocol.Protocol;
@@ -101,7 +102,7 @@ public async Task Can_List_And_Call_Registered_Prompts()
101102
await using McpClient client = await CreateMcpClientForServer();
102103

103104
var prompts = await client.ListPromptsAsync(cancellationToken: TestContext.Current.CancellationToken);
104-
Assert.Equal(6, prompts.Count);
105+
Assert.Equal(8, prompts.Count);
105106

106107
var prompt = prompts.First(t => t.Name == "returns_chat_messages");
107108
Assert.Equal("Returns chat messages", prompt.Description);
@@ -130,7 +131,7 @@ public async Task Can_Be_Notified_Of_Prompt_Changes()
130131
await using McpClient client = await CreateMcpClientForServer();
131132

132133
var prompts = await client.ListPromptsAsync(cancellationToken: TestContext.Current.CancellationToken);
133-
Assert.Equal(6, prompts.Count);
134+
Assert.Equal(8, prompts.Count);
134135

135136
Channel<JsonRpcNotification> listChanged = Channel.CreateUnbounded<JsonRpcNotification>();
136137
var notificationRead = listChanged.Reader.ReadAsync(TestContext.Current.CancellationToken);
@@ -151,7 +152,7 @@ public async Task Can_Be_Notified_Of_Prompt_Changes()
151152
await notificationRead;
152153

153154
prompts = await client.ListPromptsAsync(cancellationToken: TestContext.Current.CancellationToken);
154-
Assert.Equal(7, prompts.Count);
155+
Assert.Equal(9, prompts.Count);
155156
Assert.Contains(prompts, t => t.Name == "NewPrompt");
156157

157158
notificationRead = listChanged.Reader.ReadAsync(TestContext.Current.CancellationToken);
@@ -161,7 +162,7 @@ public async Task Can_Be_Notified_Of_Prompt_Changes()
161162
}
162163

163164
prompts = await client.ListPromptsAsync(cancellationToken: TestContext.Current.CancellationToken);
164-
Assert.Equal(6, prompts.Count);
165+
Assert.Equal(8, prompts.Count);
165166
Assert.DoesNotContain(prompts, t => t.Name == "NewPrompt");
166167
}
167168

@@ -195,6 +196,75 @@ await Assert.ThrowsAsync<McpProtocolException>(async () => await client.GetPromp
195196
cancellationToken: TestContext.Current.CancellationToken));
196197
}
197198

199+
[Fact]
200+
public async Task Logs_Prompt_Name_On_Successful_Call()
201+
{
202+
await using McpClient client = await CreateMcpClientForServer();
203+
204+
var result = await client.GetPromptAsync(
205+
"returns_chat_messages",
206+
new Dictionary<string, object?> { ["message"] = "hello" },
207+
cancellationToken: TestContext.Current.CancellationToken);
208+
209+
Assert.NotNull(result);
210+
211+
var infoLog = Assert.Single(MockLoggerProvider.LogMessages, m => m.Message == "GetPrompt \"returns_chat_messages\" completed.");
212+
Assert.Equal(LogLevel.Information, infoLog.LogLevel);
213+
}
214+
215+
[Fact]
216+
public async Task Logs_Prompt_Name_When_Prompt_Throws()
217+
{
218+
await using McpClient client = await CreateMcpClientForServer();
219+
220+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.GetPromptAsync(
221+
"throws_exception",
222+
new Dictionary<string, object?> { ["message"] = "test" },
223+
cancellationToken: TestContext.Current.CancellationToken));
224+
225+
var errorLog = Assert.Single(MockLoggerProvider.LogMessages, m => m.LogLevel == LogLevel.Error);
226+
Assert.Equal("GetPrompt \"throws_exception\" threw an unhandled exception.", errorLog.Message);
227+
Assert.IsType<FormatException>(errorLog.Exception);
228+
}
229+
230+
[Fact]
231+
public async Task Logs_Prompt_Error_When_Prompt_Throws_OperationCanceledException()
232+
{
233+
await using McpClient client = await CreateMcpClientForServer();
234+
235+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.GetPromptAsync(
236+
"throws_operation_canceled_exception",
237+
cancellationToken: TestContext.Current.CancellationToken));
238+
239+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
240+
m.LogLevel == LogLevel.Error &&
241+
m.Message == "GetPrompt \"throws_operation_canceled_exception\" threw an unhandled exception." &&
242+
m.Exception is OperationCanceledException);
243+
244+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
245+
m.LogLevel == LogLevel.Warning &&
246+
m.Message.Contains("request handler failed"));
247+
}
248+
249+
[Fact]
250+
public async Task Logs_Prompt_Error_When_Prompt_Throws_McpProtocolException()
251+
{
252+
await using McpClient client = await CreateMcpClientForServer();
253+
254+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.GetPromptAsync(
255+
"throws_mcp_protocol_exception",
256+
cancellationToken: TestContext.Current.CancellationToken));
257+
258+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
259+
m.LogLevel == LogLevel.Error &&
260+
m.Message == "GetPrompt \"throws_mcp_protocol_exception\" threw an unhandled exception." &&
261+
m.Exception is McpProtocolException);
262+
263+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
264+
m.LogLevel == LogLevel.Warning &&
265+
m.Message.Contains("request handler failed"));
266+
}
267+
198268
[Fact]
199269
public async Task Throws_Exception_On_Unknown_Prompt()
200270
{
@@ -335,6 +405,14 @@ public static ChatMessage[] ReturnsChatMessages([Description("The first paramete
335405
public static ChatMessage[] ThrowsException([Description("The first parameter")] string message) =>
336406
throw new FormatException("uh oh");
337407

408+
[McpServerPrompt, Description("Throws OperationCanceledException")]
409+
public static ChatMessage[] ThrowsOperationCanceledException() =>
410+
throw new OperationCanceledException("Prompt was canceled");
411+
412+
[McpServerPrompt, Description("Throws McpProtocolException")]
413+
public static ChatMessage[] ThrowsMcpProtocolException() =>
414+
throw new McpProtocolException("Prompt protocol error", McpErrorCode.InvalidParams);
415+
338416
[McpServerPrompt(Title = "This is a title", IconSource = "https://example.com/prompt-icon.svg"), Description("Returns chat messages")]
339417
public string ReturnsString([Description("The first parameter")] string message) =>
340418
$"The prompt is: {message}. The id is {id}.";

‎tests/ModelContextProtocol.Tests/Configuration/McpServerBuilderExtensionsResourcesTests.cs‎

Lines changed: 78 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
using Microsoft.Extensions.AI;
22
using Microsoft.Extensions.DependencyInjection;
3+
using Microsoft.Extensions.Logging;
34
using Microsoft.Extensions.Options;
45
using ModelContextProtocol.Client;
56
using ModelContextProtocol.Protocol;
@@ -130,7 +131,7 @@ public async Task Can_List_And_Call_Registered_Resources()
130131
Assert.NotNull(client.ServerCapabilities.Resources);
131132

132133
var resources = await client.ListResourcesAsync(cancellationToken: TestContext.Current.CancellationToken);
133-
Assert.Equal(5, resources.Count);
134+
Assert.Equal(7, resources.Count);
134135

135136
var resource = resources.First(t => t.Name == "some_neat_direct_resource");
136137
Assert.Equal("Some neat direct resource", resource.Description);
@@ -164,7 +165,7 @@ public async Task Can_Be_Notified_Of_Resource_Changes()
164165
await using McpClient client = await CreateMcpClientForServer();
165166

166167
var resources = await client.ListResourcesAsync(cancellationToken: TestContext.Current.CancellationToken);
167-
Assert.Equal(5, resources.Count);
168+
Assert.Equal(7, resources.Count);
168169

169170
Channel<JsonRpcNotification> listChanged = Channel.CreateUnbounded<JsonRpcNotification>();
170171
var notificationRead = listChanged.Reader.ReadAsync(TestContext.Current.CancellationToken);
@@ -185,7 +186,7 @@ public async Task Can_Be_Notified_Of_Resource_Changes()
185186
await notificationRead;
186187

187188
resources = await client.ListResourcesAsync(cancellationToken: TestContext.Current.CancellationToken);
188-
Assert.Equal(6, resources.Count);
189+
Assert.Equal(8, resources.Count);
189190
Assert.Contains(resources, t => t.Name == "NewResource");
190191

191192
notificationRead = listChanged.Reader.ReadAsync(TestContext.Current.CancellationToken);
@@ -195,7 +196,7 @@ public async Task Can_Be_Notified_Of_Resource_Changes()
195196
}
196197

197198
resources = await client.ListResourcesAsync(cancellationToken: TestContext.Current.CancellationToken);
198-
Assert.Equal(5, resources.Count);
199+
Assert.Equal(7, resources.Count);
199200
Assert.DoesNotContain(resources, t => t.Name == "NewResource");
200201
}
201202

@@ -239,6 +240,73 @@ await Assert.ThrowsAsync<McpProtocolException>(async () => await client.ReadReso
239240
cancellationToken: TestContext.Current.CancellationToken));
240241
}
241242

243+
[Fact]
244+
public async Task Logs_Resource_Uri_On_Successful_Read()
245+
{
246+
await using McpClient client = await CreateMcpClientForServer();
247+
248+
var result = await client.ReadResourceAsync(
249+
"resource://mcp/some_neat_direct_resource",
250+
cancellationToken: TestContext.Current.CancellationToken);
251+
252+
Assert.NotNull(result);
253+
254+
var infoLog = Assert.Single(MockLoggerProvider.LogMessages, m => m.Message == "ReadResource \"resource://mcp/some_neat_direct_resource\" completed.");
255+
Assert.Equal(LogLevel.Information, infoLog.LogLevel);
256+
}
257+
258+
[Fact]
259+
public async Task Logs_Resource_Uri_When_Resource_Throws()
260+
{
261+
await using McpClient client = await CreateMcpClientForServer();
262+
263+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.ReadResourceAsync(
264+
"resource://mcp/throws_exception",
265+
cancellationToken: TestContext.Current.CancellationToken));
266+
267+
var errorLog = Assert.Single(MockLoggerProvider.LogMessages, m => m.LogLevel == LogLevel.Error);
268+
Assert.Equal("ReadResource \"resource://mcp/throws_exception\" threw an unhandled exception.", errorLog.Message);
269+
Assert.IsType<InvalidOperationException>(errorLog.Exception);
270+
}
271+
272+
[Fact]
273+
public async Task Logs_Resource_Error_When_Resource_Throws_OperationCanceledException()
274+
{
275+
await using McpClient client = await CreateMcpClientForServer();
276+
277+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.ReadResourceAsync(
278+
"resource://mcp/throws_operation_canceled_exception",
279+
cancellationToken: TestContext.Current.CancellationToken));
280+
281+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
282+
m.LogLevel == LogLevel.Error &&
283+
m.Message == "ReadResource \"resource://mcp/throws_operation_canceled_exception\" threw an unhandled exception." &&
284+
m.Exception is OperationCanceledException);
285+
286+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
287+
m.LogLevel == LogLevel.Warning &&
288+
m.Message.Contains("request handler failed"));
289+
}
290+
291+
[Fact]
292+
public async Task Logs_Resource_Error_When_Resource_Throws_McpProtocolException()
293+
{
294+
await using McpClient client = await CreateMcpClientForServer();
295+
296+
await Assert.ThrowsAsync<McpProtocolException>(async () => await client.ReadResourceAsync(
297+
"resource://mcp/throws_mcp_protocol_exception",
298+
cancellationToken: TestContext.Current.CancellationToken));
299+
300+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
301+
m.LogLevel == LogLevel.Error &&
302+
m.Message == "ReadResource \"resource://mcp/throws_mcp_protocol_exception\" threw an unhandled exception." &&
303+
m.Exception is McpProtocolException);
304+
305+
Assert.Contains(MockLoggerProvider.LogMessages, m =>
306+
m.LogLevel == LogLevel.Warning &&
307+
m.Message.Contains("request handler failed"));
308+
}
309+
242310
[Fact]
243311
public async Task Throws_Exception_On_Unknown_Resource()
244312
{
@@ -361,6 +429,12 @@ public sealed class SimpleResources
361429

362430
[McpServerResource]
363431
public static string ThrowsException() => throw new InvalidOperationException("uh oh");
432+
433+
[McpServerResource]
434+
public static string ThrowsOperationCanceledException() => throw new OperationCanceledException("Resource was canceled");
435+
436+
[McpServerResource]
437+
public static string ThrowsMcpProtocolException() => throw new McpProtocolException("Resource protocol error", McpErrorCode.InvalidParams);
364438
}
365439

366440
[McpServerResourceType]

0 commit comments

Comments
 (0)