From 13d6b619efb87545de518c345628b5723f02a5a3 Mon Sep 17 00:00:00 2001 From: Stephen Toub Date: Wed, 26 Aug 2026 21:27:24 -0700 Subject: [PATCH 1/3] Log tool dispatch and handler failures in the .NET SDK CopilotSession swallowed several handler failures silently. Most notably, ExecuteToolAndRespondAsync caught every exception, reported the message back over RPC, and logged nothing -- so a host whose tool never ran saw only an external_tool.requested followed by an external_tool.completed milliseconds later, with no way to tell whether the failure came from argument binding, result conversion, or the handler itself. Add structured LoggerMessage diagnostics for the tool, permission, command, elicitation, and MCP OAuth dispatch paths, covering both the handler failure and the follow-up failure to deliver the error back to the runtime. Also warn when a tool or command request arrives for a name this client has no handler for, including the registered names, guarded by an IsEnabled check. Behavior is unchanged: errors are still reported back via the same RPCs. Tool arguments and results are never logged. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- dotnet/src/Session.cs | 165 ++++++++++++++++++++------ dotnet/test/E2E/ToolsE2ETests.cs | 8 ++ dotnet/test/Harness/E2ETestBase.cs | 20 +++- dotnet/test/Harness/E2ETestContext.cs | 22 +++- 4 files changed, 177 insertions(+), 38 deletions(-) diff --git a/dotnet/src/Session.cs b/dotnet/src/Session.cs index 7d076d14b0..eab352b236 100644 --- a/dotnet/src/Session.cs +++ b/dotnet/src/Session.cs @@ -642,7 +642,20 @@ private async Task HandleBroadcastEventAsync(SessionEvent sessionEvent) var tool = GetTool(data.ToolName); if (tool is null) - return; // This client doesn't handle this tool; another client will. + { + // This client doesn't handle this tool; another client may. Log it + // anyway: for a single-client host this is indistinguishable from a + // tool that silently never runs, and there is no other signal. + if (_logger.IsEnabled(LogLevel.Warning)) + { + LogNoToolHandlerRegistered( + SessionId, + data.RequestId, + data.ToolName, + string.Join(", ", _toolHandlers.Keys)); + } + return; + } using (TelemetryHelpers.RestoreTraceContext(data.Traceparent, data.Tracestate)) await ExecuteToolAndRespondAsync(data.RequestId, data.ToolName, data.ToolCallId, data.Arguments, tool); @@ -788,41 +801,41 @@ private async Task ExecuteMcpAuthAndRespondAsync( await Rpc.Mcp.Oauth.HandlePendingRequestAsync(requestId, response); } - catch (OperationCanceledException) + catch (OperationCanceledException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (ObjectDisposedException) + catch (ObjectDisposedException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (InvalidOperationException) + catch (InvalidOperationException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (ArgumentException) + catch (ArgumentException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (NotSupportedException) + catch (NotSupportedException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (JsonException) + catch (JsonException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (RemoteRpcException) + catch (RemoteRpcException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } - catch (IOException) + catch (IOException ex) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } catch (Exception ex) when (IsRecoverableMcpAuthFailure(ex)) { - await TryCancelMcpAuthRequestAsync(requestId); + await TryCancelMcpAuthRequestAsync(requestId, ex); } } @@ -833,23 +846,27 @@ and not StackOverflowException and not AccessViolationException and not AppDomainUnloadedException; - private async Task TryCancelMcpAuthRequestAsync(string requestId) + private async Task TryCancelMcpAuthRequestAsync(string requestId, Exception cause) { + LogMcpAuthFailed(cause, SessionId, requestId); try { await Rpc.Mcp.Oauth.HandlePendingRequestAsync(requestId, new McpOauthPendingRequestResponseCancelled()); } - catch (IOException) + catch (IOException ex) { - // Connection lost — nothing we can do. + // Connection lost — nothing we can do beyond recording it. + LogMcpAuthCancelDeliveryFailed(ex, SessionId, requestId); } - catch (ObjectDisposedException) + catch (ObjectDisposedException ex) { - // Connection already disposed — nothing we can do. + // Connection already disposed — nothing we can do beyond recording it. + LogMcpAuthCancelDeliveryFailed(ex, SessionId, requestId); } - catch (RemoteRpcException) + catch (RemoteRpcException ex) { - // The pending request may already be gone — nothing we can do. + // The pending request may already be gone — nothing we can do beyond recording it. + LogMcpAuthCancelDeliveryFailed(ex, SessionId, requestId); } } @@ -928,17 +945,23 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } catch (Exception ex) { + // The failure may come from argument binding or result conversion rather than the + // handler itself, in which case the caller's delegate never ran and this log is the + // only evidence of why. Never log the arguments or the result — they can be sensitive. + LogToolCallFailed(ex, SessionId, requestId, toolCallId, toolName); try { await Rpc.Tools.HandlePendingToolCallAsync(requestId, result: null, error: ex.Message); } - catch (IOException) + catch (IOException deliveryEx) { - // Connection lost or RPC error — nothing we can do + // Connection lost or RPC error — nothing we can do beyond recording it. + LogToolCallErrorDeliveryFailed(deliveryEx, SessionId, requestId, toolName); } - catch (ObjectDisposedException) + catch (ObjectDisposedException deliveryEx) { - // Connection already disposed — nothing we can do + // Connection already disposed — nothing we can do beyond recording it. + LogToolCallErrorDeliveryFailed(deliveryEx, SessionId, requestId, toolName); } } } @@ -982,13 +1005,15 @@ private async Task ExecutePermissionAndRespondAsync(string requestId, Permission { await Rpc.Permissions.HandlePendingPermissionRequestAsync(requestId, PermissionDecision.UserNotAvailable()); } - catch (IOException) + catch (IOException deliveryEx) { - // Connection lost or RPC error — nothing we can do + // Connection lost or RPC error — nothing we can do beyond recording it. + LogPermissionDecisionDeliveryFailed(deliveryEx, SessionId, requestId); } - catch (ObjectDisposedException) + catch (ObjectDisposedException deliveryEx) { - // Connection already disposed — nothing we can do + // Connection already disposed — nothing we can do beyond recording it. + LogPermissionDecisionDeliveryFailed(deliveryEx, SessionId, requestId); } } } @@ -1235,13 +1260,22 @@ private async Task ExecuteCommandAndRespondAsync(string requestId, string comman { if (!_commandHandlers.TryGetValue(commandName, out var handler)) { + if (_logger.IsEnabled(LogLevel.Warning)) + { + LogNoCommandHandlerRegistered( + SessionId, + requestId, + commandName, + string.Join(", ", _commandHandlers.Keys)); + } try { await Rpc.Commands.HandlePendingCommandAsync(requestId, error: $"Unknown command: {commandName}"); } catch (Exception ex) when (ex is IOException or ObjectDisposedException) { - // Connection lost — nothing we can do + // Connection lost — nothing we can do beyond recording it. + LogCommandErrorDeliveryFailed(ex, SessionId, requestId, commandName); } return; } @@ -1275,6 +1309,7 @@ await handler(new CommandContext { // User handler can throw any exception — report the error back to the server // so the pending command doesn't hang. + LogCommandFailed(error, SessionId, requestId, commandName); var message = error.Message; try { @@ -1282,7 +1317,8 @@ await handler(new CommandContext } catch (Exception ex) when (ex is IOException or ObjectDisposedException) { - // Connection lost — nothing we can do + // Connection lost — nothing we can do beyond recording it. + LogCommandErrorDeliveryFailed(ex, SessionId, requestId, commandName); } } } @@ -1322,6 +1358,7 @@ private async Task HandleElicitationRequestAsync(ElicitationContext context, str catch (Exception ex) when (ex is not OperationCanceledException) { // User handler can throw any exception — attempt to cancel so the request doesn't hang. + LogElicitationFailed(ex, SessionId, requestId); try { await Rpc.Ui.HandlePendingElicitationAsync(requestId, new UIElicitationResponse @@ -1331,7 +1368,8 @@ private async Task HandleElicitationRequestAsync(ElicitationContext context, str } catch (Exception innerEx) when (innerEx is IOException or ObjectDisposedException) { - // Connection lost — nothing we can do + // Connection lost — nothing we can do beyond recording it. + LogElicitationCancelDeliveryFailed(innerEx, SessionId, requestId); } } } @@ -1975,6 +2013,61 @@ await InvokeRpcAsync( [LoggerMessage(Level = LogLevel.Debug, Message = "Failed to fetch tool metadata for {toolName}")] private partial void LogToolMetadataFetchFailed(Exception exception, string toolName); + [LoggerMessage( + Level = LogLevel.Error, + Message = "Tool call failed before a result could be produced. SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}")] + private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deliver the tool call error back to the runtime. SessionId={SessionId}, RequestId={RequestId}, Tool={ToolName}")] + private partial void LogToolCallErrorDeliveryFailed(Exception exception, string sessionId, string requestId, string toolName); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Received a tool request for a tool this client has no handler registered for. Another connected client may handle it; otherwise the tool call will never be answered by this client. SessionId={SessionId}, RequestId={RequestId}, Tool={ToolName}, RegisteredTools=[{RegisteredTools}]")] + private partial void LogNoToolHandlerRegistered(string sessionId, string requestId, string toolName, string registeredTools); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deliver the permission decision back to the runtime. SessionId={SessionId}, RequestId={RequestId}")] + private partial void LogPermissionDecisionDeliveryFailed(Exception exception, string sessionId, string requestId); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Command handler failed. SessionId={SessionId}, RequestId={RequestId}, Command={CommandName}")] + private partial void LogCommandFailed(Exception exception, string sessionId, string requestId, string commandName); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deliver the command error back to the runtime. SessionId={SessionId}, RequestId={RequestId}, Command={CommandName}")] + private partial void LogCommandErrorDeliveryFailed(Exception exception, string sessionId, string requestId, string commandName); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Received a command request for a command this client has no handler registered for. SessionId={SessionId}, RequestId={RequestId}, Command={CommandName}, RegisteredCommands=[{RegisteredCommands}]")] + private partial void LogNoCommandHandlerRegistered(string sessionId, string requestId, string commandName, string registeredCommands); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Elicitation handler failed; cancelling the pending elicitation. SessionId={SessionId}, RequestId={RequestId}")] + private partial void LogElicitationFailed(Exception exception, string sessionId, string requestId); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deliver the elicitation cancellation back to the runtime. SessionId={SessionId}, RequestId={RequestId}")] + private partial void LogElicitationCancelDeliveryFailed(Exception exception, string sessionId, string requestId); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "MCP OAuth request failed; cancelling the pending request. SessionId={SessionId}, RequestId={RequestId}")] + private partial void LogMcpAuthFailed(Exception exception, string sessionId, string requestId); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deliver the MCP OAuth cancellation back to the runtime. SessionId={SessionId}, RequestId={RequestId}")] + private partial void LogMcpAuthCancelDeliveryFailed(Exception exception, string sessionId, string requestId); + internal record SendMessageRequest { public string SessionId { get; init; } = string.Empty; diff --git a/dotnet/test/E2E/ToolsE2ETests.cs b/dotnet/test/E2E/ToolsE2ETests.cs index ea615fbc4a..d90fbdd15b 100644 --- a/dotnet/test/E2E/ToolsE2ETests.cs +++ b/dotnet/test/E2E/ToolsE2ETests.cs @@ -5,6 +5,7 @@ using GitHub.Copilot.Rpc; using GitHub.Copilot.Test.Harness; using Microsoft.Extensions.AI; +using Microsoft.Extensions.Logging; using System.Collections.ObjectModel; using System.ComponentModel; using System.Text.Json; @@ -156,6 +157,13 @@ public async Task Handles_Tool_Calling_Errors() // exception information as if it was the tool's output. Assert.DoesNotContain("Melbourne", answer?.Data.Content); Assert.Contains("unknown", answer?.Data.Content?.ToLowerInvariant()); + + // The failure must also be diagnosable from the host: the SDK swallows the + // exception on the wire (by design) but has to leave a trace in the log. + var failureLog = Assert.Single(LogEntries, e => + e.Level == LogLevel.Error && e.Message.Contains("get_user_location", StringComparison.Ordinal)); + Assert.Contains("Tool call failed", failureLog.Message, StringComparison.Ordinal); + Assert.Equal("Melbourne", failureLog.Exception?.Message); } [Fact] diff --git a/dotnet/test/Harness/E2ETestBase.cs b/dotnet/test/Harness/E2ETestBase.cs index 3eb0f0e97a..be965ed802 100644 --- a/dotnet/test/Harness/E2ETestBase.cs +++ b/dotnet/test/Harness/E2ETestBase.cs @@ -35,15 +35,33 @@ protected E2ETestBase(E2ETestFixture fixture, string snapshotCategory, ITestOutp /// Logger that forwards warnings and above to xunit test output. protected ILogger Logger { get; } + /// + /// Warning-and-above messages the SDK logged during this test, in order. Populated by + /// , which is wired into every client created through . + /// + protected IReadOnlyList LogEntries => ((XunitLogger)Logger).Entries; + + /// A single captured log message. + protected sealed record LogEntry(LogLevel Level, string Message, Exception? Exception); + /// Bridges to xunit's . private sealed class XunitLogger(ITestOutputHelper output) : ILogger { + private readonly List _entries = []; + + public IReadOnlyList Entries + { + get { lock (_entries) { return [.. _entries]; } } + } + public IDisposable? BeginScope(TState state) where TState : notnull => null; public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Warning; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { if (!IsEnabled(logLevel)) return; - try { output.WriteLine($"[{logLevel}] {formatter(state, exception)}"); } + var message = formatter(state, exception); + lock (_entries) { _entries.Add(new LogEntry(logLevel, message, exception)); } + try { output.WriteLine($"[{logLevel}] {message}"); } catch (InvalidOperationException) { /* test already finished */ } } } diff --git a/dotnet/test/Harness/E2ETestContext.cs b/dotnet/test/Harness/E2ETestContext.cs index 0080cbc609..b10da125a6 100644 --- a/dotnet/test/Harness/E2ETestContext.cs +++ b/dotnet/test/Harness/E2ETestContext.cs @@ -25,6 +25,7 @@ public sealed class E2ETestContext : IAsyncDisposable private readonly ReplayProxy _proxy; private readonly string _repoRoot; + private readonly ILogger _loggerForwarder; private readonly object _clientsLock = new(); private readonly List _persistentClients = []; private readonly List _transientClients = []; @@ -36,6 +37,25 @@ private E2ETestContext(string homeDir, string workDir, string proxyUrl, ReplayPr ProxyUrl = proxyUrl; _proxy = proxy; _repoRoot = repoRoot; + _loggerForwarder = new CurrentLoggerForwarder(this); + } + + /// + /// Forwards log calls to whatever is current at the time of the call. + /// A captures its logger at construction, and the shared + /// persistent client is constructed before any test assigns ; forwarding + /// lets its SDK-side warnings and errors still reach the test that is currently running. + /// + private sealed class CurrentLoggerForwarder(E2ETestContext context) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull + => context.Logger?.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) + => context.Logger?.IsEnabled(logLevel) ?? false; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + => context.Logger?.Log(logLevel, eventId, state, exception, formatter); } public static async Task CreateAsync() @@ -276,7 +296,7 @@ public CopilotClient CreateClient( { options ??= new CopilotClientOptions(); - options.Logger ??= Logger; + options.Logger ??= _loggerForwarder; // Resolve the working directory the worker should run in. Child-process and // URI transports take it as a per-client option; the in-process transport From 469d380971b9d4eeea39c266b800a4bae3084d11 Mon Sep 17 00:00:00 2001 From: Stephen Toub Date: Thu, 27 Aug 2026 06:14:36 -0700 Subject: [PATCH 2/3] Name the failing stage in the tool call failure log The outer catch in ExecuteToolAndRespondAsync also covers the success-path HandlePendingToolCallAsync, so 'failed before a result could be produced' was wrong whenever the handler succeeded and delivery failed -- reporting a transport failure as if the handler never produced anything. Track the stage the call reached and log it, which is both accurate for every path and more useful than a message that merely covers both: it separates argument binding (handler never ran) from a handler that threw, from a result that could not be converted or delivered. Apply the same correction to the command and elicitation messages, matching the 'handler or response delivery failed' wording the permission path already used. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- dotnet/src/Session.cs | 39 +++++++++++++++++++++++++------- dotnet/test/E2E/ToolsE2ETests.cs | 5 +++- 2 files changed, 35 insertions(+), 9 deletions(-) diff --git a/dotnet/src/Session.cs b/dotnet/src/Session.cs index eab352b236..4964134c82 100644 --- a/dotnet/src/Session.cs +++ b/dotnet/src/Session.cs @@ -875,6 +875,10 @@ private async Task TryCancelMcpAuthRequestAsync(string requestId, Exception caus /// private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, string toolCallId, JsonElement? arguments, AIFunction tool) { + // Tracks how far the call got so a failure can name the stage it died in. From the + // outside, "the arguments never bound" and "the connection dropped after the handler + // succeeded" otherwise look identical: both surface only as a completed tool call. + var stage = ToolCallStage.PreparingArguments; try { var invocation = new ToolInvocation @@ -922,6 +926,7 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } var toolTimestamp = Stopwatch.GetTimestamp(); + stage = ToolCallStage.InvokingHandler; var result = await tool.InvokeAsync(aiFunctionArgs); LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null, "CopilotSession.ExecuteToolAndRespondAsync tool dispatch. Elapsed={Elapsed}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}", @@ -931,9 +936,11 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, toolCallId, toolName); + stage = ToolCallStage.ConvertingResult; var toolResultObject = ToolResultObject.ConvertFromInvocationResult(result, tool.JsonSerializerOptions); var responseRpcTimestamp = Stopwatch.GetTimestamp(); + stage = ToolCallStage.SendingResult; await Rpc.Tools.HandlePendingToolCallAsync(requestId, toolResultObject, error: null); LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null, "CopilotSession.ExecuteToolAndRespondAsync response sent successfully. Elapsed={Elapsed}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}", @@ -945,10 +952,10 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } catch (Exception ex) { - // The failure may come from argument binding or result conversion rather than the - // handler itself, in which case the caller's delegate never ran and this log is the - // only evidence of why. Never log the arguments or the result — they can be sensitive. - LogToolCallFailed(ex, SessionId, requestId, toolCallId, toolName); + // Stage distinguishes a handler that threw from one that never ran at all (argument + // binding) and from a result that was produced but could not be delivered. Never log + // the arguments or the result — they can be sensitive. + LogToolCallFailed(ex, SessionId, requestId, toolCallId, toolName, stage); try { await Rpc.Tools.HandlePendingToolCallAsync(requestId, result: null, error: ex.Message); @@ -2015,8 +2022,24 @@ await InvokeRpcAsync( [LoggerMessage( Level = LogLevel.Error, - Message = "Tool call failed before a result could be produced. SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}")] - private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName); + Message = "Tool call failed. Stage={Stage}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}")] + private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName, ToolCallStage stage); + + /// Identifies how far a tool call got before it failed. + private enum ToolCallStage + { + /// Unpacking the incoming JSON arguments. The handler has not been called. + PreparingArguments, + + /// Inside , which binds arguments before running the handler body — so the handler itself may still never have run. + InvokingHandler, + + /// Converting the handler's return value for the wire. The handler succeeded. + ConvertingResult, + + /// Sending the successful result back to the runtime. The handler succeeded. + SendingResult, + } [LoggerMessage( Level = LogLevel.Warning, @@ -2035,7 +2058,7 @@ await InvokeRpcAsync( [LoggerMessage( Level = LogLevel.Error, - Message = "Command handler failed. SessionId={SessionId}, RequestId={RequestId}, Command={CommandName}")] + Message = "Command handler or response delivery failed. SessionId={SessionId}, RequestId={RequestId}, Command={CommandName}")] private partial void LogCommandFailed(Exception exception, string sessionId, string requestId, string commandName); [LoggerMessage( @@ -2050,7 +2073,7 @@ await InvokeRpcAsync( [LoggerMessage( Level = LogLevel.Error, - Message = "Elicitation handler failed; cancelling the pending elicitation. SessionId={SessionId}, RequestId={RequestId}")] + Message = "Elicitation handler or response delivery failed; cancelling the pending elicitation. SessionId={SessionId}, RequestId={RequestId}")] private partial void LogElicitationFailed(Exception exception, string sessionId, string requestId); [LoggerMessage( diff --git a/dotnet/test/E2E/ToolsE2ETests.cs b/dotnet/test/E2E/ToolsE2ETests.cs index d90fbdd15b..41055273db 100644 --- a/dotnet/test/E2E/ToolsE2ETests.cs +++ b/dotnet/test/E2E/ToolsE2ETests.cs @@ -159,10 +159,13 @@ public async Task Handles_Tool_Calling_Errors() Assert.Contains("unknown", answer?.Data.Content?.ToLowerInvariant()); // The failure must also be diagnosable from the host: the SDK swallows the - // exception on the wire (by design) but has to leave a trace in the log. + // exception on the wire (by design) but has to leave a trace in the log, + // including the stage so a handler that threw is distinguishable from one + // that never ran. var failureLog = Assert.Single(LogEntries, e => e.Level == LogLevel.Error && e.Message.Contains("get_user_location", StringComparison.Ordinal)); Assert.Contains("Tool call failed", failureLog.Message, StringComparison.Ordinal); + Assert.Contains("Stage=InvokingHandler", failureLog.Message, StringComparison.Ordinal); Assert.Equal("Melbourne", failureLog.Exception?.Message); } From aa5155cb283973a74c9c212a230087ebd287e60d Mon Sep 17 00:00:00 2001 From: Stephen Toub Date: Thu, 27 Aug 2026 07:17:37 -0700 Subject: [PATCH 3/3] Simplify stage tracking and extend dispatch logging to all SDKs Replace the private ToolCallStage enum in the .NET SDK with plain string literals. The rendered log output is identical, since the enum was only ever formatted via ToString(), and strings let the same stage values be shared verbatim across every SDK. Port the handler dispatch diagnostics to the Python, Go, Node.js, Java, and Rust SDKs so a handler that fails to bind or throws is diagnosable from the host in every language rather than only in C#. Each SDK follows its own existing logging convention: module logger with lazy %s formatting in Python, level-gated log.Printf in Go, console.warn/error in Node.js, java.util.logging with lazy suppliers in Java, and tracing with structured fields in Rust. Behavior is unchanged. Errors are still reported back over the same RPC calls, and only tool names and request/session identifiers are logged, never argument payloads or results. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- dotnet/src/Session.cs | 28 +- go/client.go | 2 + go/github_token_provider_test.go | 4 +- go/session.go | 367 ++++++++++++++++-- .../com/github/copilot/CopilotSession.java | 154 +++++++- nodejs/src/session.ts | 109 +++++- nodejs/test/client.test.ts | 297 +++++++++++++- python/copilot/session.py | 211 +++++++++- python/copilot/tools.py | 2 + python/test_session.py | 285 +++++++++++++- rust/src/session.rs | 324 +++++++++++++--- 11 files changed, 1625 insertions(+), 158 deletions(-) diff --git a/dotnet/src/Session.cs b/dotnet/src/Session.cs index 4964134c82..3fde912251 100644 --- a/dotnet/src/Session.cs +++ b/dotnet/src/Session.cs @@ -878,7 +878,7 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, // Tracks how far the call got so a failure can name the stage it died in. From the // outside, "the arguments never bound" and "the connection dropped after the handler // succeeded" otherwise look identical: both surface only as a completed tool call. - var stage = ToolCallStage.PreparingArguments; + var stage = "PreparingArguments"; try { var invocation = new ToolInvocation @@ -926,7 +926,9 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } var toolTimestamp = Stopwatch.GetTimestamp(); - stage = ToolCallStage.InvokingHandler; + // InvokeAsync binds the arguments before running the handler body, so a failure at + // this stage does not guarantee the handler itself ran. + stage = "InvokingHandler"; var result = await tool.InvokeAsync(aiFunctionArgs); LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null, "CopilotSession.ExecuteToolAndRespondAsync tool dispatch. Elapsed={Elapsed}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}", @@ -936,11 +938,11 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, toolCallId, toolName); - stage = ToolCallStage.ConvertingResult; + stage = "ConvertingResult"; var toolResultObject = ToolResultObject.ConvertFromInvocationResult(result, tool.JsonSerializerOptions); var responseRpcTimestamp = Stopwatch.GetTimestamp(); - stage = ToolCallStage.SendingResult; + stage = "SendingResult"; await Rpc.Tools.HandlePendingToolCallAsync(requestId, toolResultObject, error: null); LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null, "CopilotSession.ExecuteToolAndRespondAsync response sent successfully. Elapsed={Elapsed}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}", @@ -2023,23 +2025,7 @@ await InvokeRpcAsync( [LoggerMessage( Level = LogLevel.Error, Message = "Tool call failed. Stage={Stage}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}")] - private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName, ToolCallStage stage); - - /// Identifies how far a tool call got before it failed. - private enum ToolCallStage - { - /// Unpacking the incoming JSON arguments. The handler has not been called. - PreparingArguments, - - /// Inside , which binds arguments before running the handler body — so the handler itself may still never have run. - InvokingHandler, - - /// Converting the handler's return value for the wire. The handler succeeded. - ConvertingResult, - - /// Sending the successful result back to the runtime. The handler succeeded. - SendingResult, - } + private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName, string stage); [LoggerMessage( Level = LogLevel.Warning, diff --git a/go/client.go b/go/client.go index 4e44696a55..610fd624be 100644 --- a/go/client.go +++ b/go/client.go @@ -970,6 +970,7 @@ func (c *Client) CreateSession(ctx context.Context, config *SessionConfig) (*Ses c.client, "", hasManagedSettings(config.EnableManagedSettings, config.ManagedSettings), + c.options.LogLevel, ) s.registerTools(config.Tools) @@ -1327,6 +1328,7 @@ func (c *Client) ResumeSessionWithOptions(ctx context.Context, sessionID string, c.client, "", hasManagedSettings(config.EnableManagedSettings, config.ManagedSettings), + c.options.LogLevel, ) session.registerTools(config.Tools) diff --git a/go/github_token_provider_test.go b/go/github_token_provider_test.go index f00837379f..68e2f23638 100644 --- a/go/github_token_provider_test.go +++ b/go/github_token_provider_test.go @@ -208,7 +208,7 @@ func TestGitHubTokenProviderCleanupOnDisconnectError(t *testing.T) { registrationID := client.registerGitHubTokenProvider(func(GitHubTokenProviderArgs) (*GitHubTokenProviderResult, error) { return GitHubTokenCancelled(), nil }) - session := newSession("cleanup-session", rpcClient, "", false) + session := newSession("cleanup-session", rpcClient, "", false, "") session.setGitHubTokenProviderRegistrationRelease(func() { client.unregisterGitHubTokenProvider(registrationID) }) @@ -252,7 +252,7 @@ func TestGitHubTokenProviderCleanupOnDelete(t *testing.T) { registrationID := client.registerGitHubTokenProvider(func(GitHubTokenProviderArgs) (*GitHubTokenProviderResult, error) { return GitHubTokenCancelled(), nil }) - session := newSession("delete-session", rpcClient, "", false) + session := newSession("delete-session", rpcClient, "", false, "") session.setGitHubTokenProviderRegistrationRelease(func() { client.unregisterGitHubTokenProvider(registrationID) }) diff --git a/go/session.go b/go/session.go index 5d45d19ef2..721ed99587 100644 --- a/go/session.go +++ b/go/session.go @@ -6,6 +6,8 @@ import ( "encoding/json" "fmt" "log" + "sort" + "strings" "sync" "time" @@ -18,6 +20,13 @@ import ( // exact name and OverridesBuiltInTool set to true. const toolSearchToolName = "tool_search_tool" +const ( + dispatchStagePreparingArguments = "PreparingArguments" + dispatchStageInvokingHandler = "InvokingHandler" + dispatchStageConvertingResult = "ConvertingResult" + dispatchStageSendingResult = "SendingResult" +) + type sessionHandler struct { id uint64 fn SessionEventHandler @@ -95,6 +104,7 @@ type Session struct { openCanvasesMu sync.RWMutex capabilities SessionCapabilities capabilitiesMu sync.RWMutex + logLevel string // eventCh serializes user event handler dispatch. dispatchEvent enqueues; // a single goroutine (processEvents) dequeues and invokes handlers in FIFO order. @@ -112,6 +122,36 @@ func (s *Session) WorkspacePath() string { return s.workspacePath } +func (s *Session) logWarningEnabled() bool { + switch strings.ToLower(s.logLevel) { + case "warning", "info", "debug", "all": + return true + default: + return false + } +} + +func (s *Session) logErrorEnabled() bool { + switch strings.ToLower(s.logLevel) { + case "error", "warning", "info", "debug", "all": + return true + default: + return false + } +} + +func (s *Session) logWarnf(format string, args ...any) { + if s.logWarningEnabled() { + log.Printf("WARNING: "+format, args...) + } +} + +func (s *Session) logErrorf(format string, args ...any) { + if s.logErrorEnabled() { + log.Printf("ERROR: "+format, args...) + } +} + // OpenCanvases returns the open-canvas snapshot last reported by the runtime. // The snapshot is populated from session.resume and live session.canvas.opened // and session.canvas.closed events. The returned slice is a copy and is safe to @@ -374,11 +414,13 @@ func newSession( client *jsonrpc2.Client, workspacePath string, managedSettings bool, + logLevel string, ) *Session { s := &Session{ SessionID: sessionID, workspacePath: workspacePath, managedSettings: managedSettings, + logLevel: logLevel, client: client, clientSessionAPIs: &rpc.ClientSessionAPIHandlers{}, handlers: make([]sessionHandler, 0), @@ -613,6 +655,18 @@ func (s *Session) getToolHandler(name string) (ToolHandler, bool) { return handler, ok } +func (s *Session) registeredToolNamesForLog() string { + s.toolHandlersM.RLock() + defer s.toolHandlersM.RUnlock() + + names := make([]string, 0, len(s.toolHandlers)) + for name := range s.toolHandlers { + names = append(names, name) + } + sort.Strings(names) + return strings.Join(names, ", ") +} + // registerPermissionHandler registers a permission handler for this session. // // When the assistant needs permission to perform certain actions (e.g., file @@ -918,17 +972,46 @@ func (s *Session) getCommandHandler(name string) (CommandHandler, bool) { return handler, ok } +func (s *Session) registeredCommandNamesForLog() string { + s.commandHandlersMu.RLock() + defer s.commandHandlersMu.RUnlock() + + names := make([]string, 0, len(s.commandHandlers)) + for name := range s.commandHandlers { + names = append(names, name) + } + sort.Strings(names) + return strings.Join(names, ", ") +} + // executeCommandAndRespond dispatches a command.execute event to the registered handler // and sends the result (or error) back via the RPC layer. func (s *Session) executeCommandAndRespond(requestID, commandName, command, args string) { ctx := context.Background() handler, ok := s.getCommandHandler(commandName) if !ok { + if s.logWarningEnabled() { + s.logWarnf( + "Received command request without a registered command handler. SessionId=%s, RequestId=%s, CommandName=%s, RegisteredCommandNames=%s", + s.SessionID, + requestID, + commandName, + s.registeredCommandNamesForLog(), + ) + } errMsg := fmt.Sprintf("Unknown command: %s", commandName) - s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ + if _, rpcErr := s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ RequestID: requestID, Error: &errMsg, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver command error over RPC. SessionId=%s, RequestId=%s, CommandName=%s, Error=%v", + s.SessionID, + requestID, + commandName, + rpcErr, + ) + } return } @@ -940,17 +1023,43 @@ func (s *Session) executeCommandAndRespond(requestID, commandName, command, args } if err := handler(cmdCtx); err != nil { + s.logErrorf( + "Command handler failed. SessionId=%s, RequestId=%s, CommandName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + commandName, + dispatchStageInvokingHandler, + err, + ) errMsg := err.Error() - s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ + if _, rpcErr := s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ RequestID: requestID, Error: &errMsg, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver command error over RPC. SessionId=%s, RequestId=%s, CommandName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + commandName, + dispatchStageInvokingHandler, + rpcErr, + ) + } return } - s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ + if _, rpcErr := s.RPC.Commands.HandlePendingCommand(ctx, &rpc.CommandsHandlePendingCommandRequest{ RequestID: requestID, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver command result over RPC. SessionId=%s, RequestId=%s, CommandName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + commandName, + dispatchStageSendingResult, + rpcErr, + ) + } } // registerElicitationHandler registers an elicitation handler for this session. @@ -982,6 +1091,11 @@ func (s *Session) getMCPAuthHandler() MCPAuthHandler { func (s *Session) handleMCPAuthRequest(request MCPAuthRequest) { handler := s.getMCPAuthHandler() if handler == nil { + s.logWarnf( + "Received MCP OAuth request without a registered MCP auth handler. SessionId=%s, RequestId=%s", + s.SessionID, + request.RequestID, + ) return } @@ -989,29 +1103,50 @@ func (s *Session) handleMCPAuthRequest(request MCPAuthRequest) { cancel := &rpc.MCPOauthPendingRequestResponseCancelled{} result, err := handler(request, MCPAuthInvocation{SessionID: s.SessionID}) if err != nil { - log.Printf( - "MCP OAuth handler failed. SessionId=%s, RequestId=%s, Error=%v", + s.logErrorf( + "MCP OAuth handler failed. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", s.SessionID, request.RequestID, + dispatchStageInvokingHandler, err, ) } if err != nil || result == nil || result.Kind == MCPAuthResultKindCancelled || result.Token == nil { - s.RPC.MCP.Oauth().HandlePendingRequest(ctx, &rpc.MCPOauthHandlePendingRequest{ + deliveryStage := dispatchStageSendingResult + if err != nil { + deliveryStage = dispatchStageInvokingHandler + } + if _, rpcErr := s.RPC.MCP.Oauth().HandlePendingRequest(ctx, &rpc.MCPOauthHandlePendingRequest{ RequestID: request.RequestID, Result: cancel, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver MCP OAuth cancellation over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + request.RequestID, + deliveryStage, + rpcErr, + ) + } return } - s.RPC.MCP.Oauth().HandlePendingRequest(ctx, &rpc.MCPOauthHandlePendingRequest{ + if _, rpcErr := s.RPC.MCP.Oauth().HandlePendingRequest(ctx, &rpc.MCPOauthHandlePendingRequest{ RequestID: request.RequestID, Result: &rpc.MCPOauthPendingRequestResponseToken{ AccessToken: result.Token.AccessToken, TokenType: result.Token.TokenType, ExpiresIn: result.Token.ExpiresIn, }, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver MCP OAuth result over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + request.RequestID, + dispatchStageSendingResult, + rpcErr, + ) + } } // handleElicitationRequest dispatches an elicitation.requested event to the registered handler @@ -1019,6 +1154,11 @@ func (s *Session) handleMCPAuthRequest(request MCPAuthRequest) { func (s *Session) handleElicitationRequest(elicitCtx ElicitationContext, requestID string) { handler := s.getElicitationHandler() if handler == nil { + s.logWarnf( + "Received elicitation request without a registered elicitation handler. SessionId=%s, RequestId=%s", + s.SessionID, + requestID, + ) return } @@ -1026,13 +1166,28 @@ func (s *Session) handleElicitationRequest(elicitCtx ElicitationContext, request result, err := handler(elicitCtx) if err != nil { + s.logErrorf( + "Elicitation handler failed. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageInvokingHandler, + err, + ) // Handler failed — attempt to cancel so the request doesn't hang. - s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ + if _, rpcErr := s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ RequestID: requestID, Result: rpc.UIElicitationResponse{ Action: rpc.UIElicitationResponseActionCancel, }, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver elicitation cancellation over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageInvokingHandler, + rpcErr, + ) + } return } @@ -1042,25 +1197,48 @@ func (s *Session) handleElicitationRequest(elicitCtx ElicitationContext, request for k, v := range result.Content { contentValue, err := toRPCContent(v) if err != nil { - s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ + s.logErrorf( + "Elicitation result conversion failed. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageConvertingResult, + err, + ) + if _, rpcErr := s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ RequestID: requestID, Result: rpc.UIElicitationResponse{ Action: rpc.UIElicitationResponseActionCancel, }, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver elicitation cancellation over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageConvertingResult, + rpcErr, + ) + } return } rpcContent[k] = contentValue } } - s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ + if _, rpcErr := s.RPC.UI.HandlePendingElicitation(ctx, &rpc.UIHandlePendingElicitationRequest{ RequestID: requestID, Result: rpc.UIElicitationResponse{ Action: result.Action, Content: rpcContent, }, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver elicitation result over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageSendingResult, + rpcErr, + ) + } } // toRPCContent converts an SDK content value to an RPC elicitation response value. @@ -1439,6 +1617,16 @@ func (s *Session) handleBroadcastEvent(event SessionEvent) { case *ExternalToolRequestedData: handler, ok := s.getToolHandler(d.ToolName) if !ok { + if s.logWarningEnabled() { + s.logWarnf( + "Received tool request for an unregistered tool. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, RegisteredToolNames=%s", + s.SessionID, + d.RequestID, + d.ToolCallID, + d.ToolName, + s.registeredToolNamesForLog(), + ) + } return } var tp, ts string @@ -1456,6 +1644,11 @@ func (s *Session) handleBroadcastEvent(event SessionEvent) { } handler := s.getPermissionHandler() if handler == nil { + s.logWarnf( + "Received permission request without a registered permission handler. SessionId=%s, RequestId=%s", + s.SessionID, + d.RequestID, + ) return } s.executePermissionAndRespond(d.RequestID, d.PermissionRequest, handler) @@ -1466,7 +1659,7 @@ func (s *Session) handleBroadcastEvent(event SessionEvent) { return } if handler == nil { - log.Printf( + s.logWarnf( "Received MCP OAuth request without a registered MCP auth handler. SessionId=%s, RequestId=%s", s.SessionID, d.RequestID, @@ -1512,6 +1705,11 @@ func (s *Session) handleBroadcastEvent(event SessionEvent) { case *ElicitationRequestedData: handler := s.getElicitationHandler() if handler == nil { + s.logWarnf( + "Received elicitation request without a registered elicitation handler. SessionId=%s, RequestId=%s", + s.SessionID, + d.RequestID, + ) return } s.handleElicitationRequest(ElicitationContext{ @@ -1535,13 +1733,33 @@ func (s *Session) handleBroadcastEvent(event SessionEvent) { // executeToolAndRespond executes a tool handler and sends the result back via RPC. func (s *Session) executeToolAndRespond(requestID, toolName, toolCallID string, arguments any, handler ToolHandler, traceparent, tracestate string) { ctx := contextWithTraceParent(context.Background(), traceparent, tracestate) + stage := dispatchStagePreparingArguments defer func() { if r := recover(); r != nil { + s.logErrorf( + "Tool dispatch failed. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + toolCallID, + toolName, + stage, + r, + ) errMsg := fmt.Sprintf("tool panic: %v", r) - s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ + if _, rpcErr := s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ RequestID: requestID, Error: &errMsg, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver tool error over RPC. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + toolCallID, + toolName, + stage, + rpcErr, + ) + } } }() @@ -1564,16 +1782,37 @@ func (s *Session) executeToolAndRespond(requestID, toolName, toolCallID string, } } + stage = dispatchStageInvokingHandler result, err := handler(invocation) if err != nil { + s.logErrorf( + "Tool dispatch failed. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + toolCallID, + toolName, + dispatchStageInvokingHandler, + err, + ) errMsg := err.Error() - s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ + if _, rpcErr := s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ RequestID: requestID, Error: &errMsg, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver tool error over RPC. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + toolCallID, + toolName, + dispatchStageInvokingHandler, + rpcErr, + ) + } return } + stage = dispatchStageConvertingResult textResultForLLM := result.TextResultForLLM if textResultForLLM == "" { textResultForLLM = fmt.Sprintf("%v", result) @@ -1612,20 +1851,47 @@ func (s *Session) executeToolAndRespond(requestID, toolName, toolCallID string, } rpcResult.BinaryResultsForLlm = append(rpcResult.BinaryResultsForLlm, entry) } - s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ + stage = dispatchStageSendingResult + if _, rpcErr := s.RPC.Tools.HandlePendingToolCall(ctx, &rpc.HandlePendingToolCallRequest{ RequestID: requestID, Result: rpcResult, - }) + }); rpcErr != nil { + s.logErrorf( + "Tool dispatch failed. SessionId=%s, RequestId=%s, ToolCallId=%s, ToolName=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + toolCallID, + toolName, + dispatchStageSendingResult, + rpcErr, + ) + } } // executePermissionAndRespond executes a permission handler and sends the result back via RPC. func (s *Session) executePermissionAndRespond(requestID string, permissionRequest PermissionRequest, handler PermissionHandlerFunc) { + stage := dispatchStageInvokingHandler defer func() { if r := recover(); r != nil { - s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ + s.logErrorf( + "Permission dispatch failed. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + stage, + r, + ) + if _, rpcErr := s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ RequestID: requestID, Result: &rpc.PermissionDecisionUserNotAvailable{}, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver permission error over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + stage, + rpcErr, + ) + } } }() @@ -1636,25 +1902,49 @@ func (s *Session) executePermissionAndRespond(requestID string, permissionReques decision, err := handler(permissionRequest, invocation) if err != nil { - log.Printf("permission handler failed: session_id=%s request_id=%s error=%v", s.SessionID, requestID, err) - s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ + s.logErrorf( + "Permission handler failed. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageInvokingHandler, + err, + ) + if _, rpcErr := s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ RequestID: requestID, Result: &rpc.PermissionDecisionUserNotAvailable{}, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver permission error over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageInvokingHandler, + rpcErr, + ) + } return } if decision == nil { // Handler returned (nil, nil); treat as user-not-available rather // than sending null on the wire. - s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ + stage = dispatchStageSendingResult + if _, rpcErr := s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ RequestID: requestID, Result: &rpc.PermissionDecisionUserNotAvailable{}, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver permission result over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageSendingResult, + rpcErr, + ) + } return } // Unwrap any attribution so decisionContext travels as a sibling of result, // not nested inside it. The suppression and send logic below operates on the // underlying decision. + stage = dispatchStageConvertingResult decision, decisionContext := splitAttribution(decision) if _, ok := decision.(*rpc.PermissionDecisionNoResult); ok { return @@ -1663,11 +1953,20 @@ func (s *Session) executePermissionAndRespond(requestID string, permissionReques return } - s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ + stage = dispatchStageSendingResult + if _, rpcErr := s.RPC.Permissions.HandlePendingPermissionRequest(context.Background(), &rpc.PermissionDecisionRequest{ RequestID: requestID, Result: decision, DecisionContext: decisionContext, - }) + }); rpcErr != nil { + s.logWarnf( + "Failed to deliver permission result over RPC. SessionId=%s, RequestId=%s, Stage=%s, Error=%v", + s.SessionID, + requestID, + dispatchStageSendingResult, + rpcErr, + ) + } } // GetEvents retrieves all events from this session's history. diff --git a/java/sdk/src/main/java/com/github/copilot/CopilotSession.java b/java/sdk/src/main/java/com/github/copilot/CopilotSession.java index f3a35967d3..6c773ba3db 100644 --- a/java/sdk/src/main/java/com/github/copilot/CopilotSession.java +++ b/java/sdk/src/main/java/com/github/copilot/CopilotSession.java @@ -12,8 +12,10 @@ import java.util.Map; import java.util.Set; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CompletionException; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.Executor; +import java.util.concurrent.ExecutionException; import java.util.concurrent.RejectedExecutionException; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledFuture; @@ -853,6 +855,7 @@ private void handleBroadcastEventAsync(SessionEvent event) { } ToolDefinition tool = getTool(data.toolName()); if (tool == null) { + logNoToolHandlerRegistered(data.requestId(), data.toolName()); return; // This client doesn't handle this tool; another client will } executeToolAndRespondAsync(data.requestId(), data.toolName(), data.toolCallId(), data.arguments(), tool); @@ -867,6 +870,7 @@ private void handleBroadcastEventAsync(SessionEvent event) { } PermissionHandler handler = permissionHandler.get(); if (handler == null) { + logNoPermissionHandlerRegistered(data.requestId()); return; // This client doesn't handle permissions; another client will } executePermissionAndRespondAsync(data.requestId(), @@ -908,6 +912,8 @@ private void handleBroadcastEventAsync(SessionEvent event) { .setRequestedSchema(schema).setMode(data.mode() != null ? data.mode().getValue() : null) .setElicitationSource(data.elicitationSource()).setUrl(data.url()); handleElicitationRequestAsync(context, data.requestId()); + } else { + logNoElicitationHandlerRegistered(data.requestId()); } } else if (event instanceof CapabilitiesChangedEvent capEvent) { var data = capEvent.getData(); @@ -956,6 +962,7 @@ void populateToolSearchMetadata(String toolName, com.github.copilot.rpc.ToolInvo private void executeToolAndRespondAsync(String requestId, String toolName, String toolCallId, Object arguments, ToolDefinition tool) { Runnable task = () -> { + String stage = "PreparingArguments"; try { JsonNode argumentsNode = arguments instanceof JsonNode jn ? jn @@ -965,7 +972,9 @@ private void executeToolAndRespondAsync(String requestId, String toolName, Strin populateToolSearchMetadata(toolName, invocation); + stage = "InvokingHandler"; tool.handler().invoke(invocation).thenAccept(result -> { + String responseStage = "ConvertingResult"; try { ToolResultObject toolResult; if (result instanceof ToolResultObject tr) { @@ -974,27 +983,30 @@ private void executeToolAndRespondAsync(String requestId, String toolName, Strin toolResult = ToolResultObject .success(result instanceof String s ? s : MAPPER.writeValueAsString(result)); } + responseStage = "SendingResult"; getRpc().tools.handlePendingToolCall( new SessionToolsHandlePendingToolCallParams(sessionId, requestId, toolResult, null)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending tool result for requestId=" + requestId, e); + logToolCallFailed(e, requestId, toolCallId, toolName, responseStage); } }).exceptionally(ex -> { + logToolCallFailed(unwrapCompletionException(ex), requestId, toolCallId, toolName, + "InvokingHandler"); try { getRpc().tools.handlePendingToolCall(new SessionToolsHandlePendingToolCallParams(sessionId, requestId, null, ex.getMessage() != null ? ex.getMessage() : ex.toString())); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending tool error for requestId=" + requestId, e); + logToolCallErrorDeliveryFailed(e, requestId, toolName); } return null; }); } catch (Exception e) { - LOG.log(Level.WARNING, "Error executing tool for requestId=" + requestId, e); + logToolCallFailed(e, requestId, toolCallId, toolName, stage); try { getRpc().tools.handlePendingToolCall(new SessionToolsHandlePendingToolCallParams(sessionId, requestId, null, e.getMessage() != null ? e.getMessage() : e.toString())); } catch (Exception sendEx) { - LOG.log(Level.WARNING, "Error sending tool error for requestId=" + requestId, sendEx); + logToolCallErrorDeliveryFailed(sendEx, requestId, toolName); } } }; @@ -1020,6 +1032,95 @@ private SessionUiHandlePendingElicitationParams buildElicitationCancelParams(Str return new SessionUiHandlePendingElicitationParams(sessionId, requestId, cancelResult); } + private static Throwable unwrapCompletionException(Throwable throwable) { + if ((throwable instanceof CompletionException || throwable instanceof ExecutionException) + && throwable.getCause() != null) { + return throwable.getCause(); + } + return throwable; + } + + private void logToolCallFailed(Throwable exception, String requestId, String toolCallId, String toolName, + String stage) { + LOG.log(Level.SEVERE, "Tool call failed. Stage=" + stage + ", SessionId=" + sessionId + ", RequestId=" + + requestId + ", ToolCallId=" + toolCallId + ", Tool=" + toolName, exception); + } + + private void logToolCallErrorDeliveryFailed(Throwable exception, String requestId, String toolName) { + LOG.log(Level.WARNING, "Failed to deliver the tool call error back to the runtime. SessionId=" + sessionId + + ", RequestId=" + requestId + ", Tool=" + toolName, exception); + } + + private void logNoToolHandlerRegistered(String requestId, String toolName) { + if (LOG.isLoggable(Level.WARNING)) { + LOG.warning("Received a tool request for a tool this client has no handler registered for. " + + "Another connected client may handle it; otherwise the tool call will never be answered by " + + "this client. SessionId=" + sessionId + ", RequestId=" + requestId + ", Tool=" + toolName + + ", RegisteredTools=[" + String.join(", ", toolHandlers.keySet()) + "]"); + } + } + + private void logPermissionFailed(Throwable exception, String requestId) { + LOG.log(Level.SEVERE, + "Permission handler or response delivery failed. SessionId=" + sessionId + ", RequestId=" + requestId, + exception); + } + + private void logPermissionDecisionDeliveryFailed(Throwable exception, String requestId) { + LOG.log(Level.WARNING, "Failed to deliver the permission decision back to the runtime. SessionId=" + sessionId + + ", RequestId=" + requestId, exception); + } + + private void logNoPermissionHandlerRegistered(String requestId) { + LOG.warning(() -> "Received a permission request without a registered permission handler. " + + "Another connected client may handle it; otherwise the permission request will never be answered " + + "by this client. SessionId=" + sessionId + ", RequestId=" + requestId); + } + + private void logCommandFailed(Throwable exception, String requestId, String commandName) { + LOG.log(Level.SEVERE, "Command handler or response delivery failed. SessionId=" + sessionId + ", RequestId=" + + requestId + ", Command=" + commandName, exception); + } + + private void logCommandErrorDeliveryFailed(Throwable exception, String requestId, String commandName) { + LOG.log(Level.WARNING, "Failed to deliver the command error back to the runtime. SessionId=" + sessionId + + ", RequestId=" + requestId + ", Command=" + commandName, exception); + } + + private void logNoCommandHandlerRegistered(String requestId, String commandName) { + if (LOG.isLoggable(Level.WARNING)) { + LOG.warning("Received a command request for a command this client has no handler registered for. SessionId=" + + sessionId + ", RequestId=" + requestId + ", Command=" + commandName + ", RegisteredCommands=[" + + String.join(", ", commandHandlers.keySet()) + "]"); + } + } + + private void logElicitationFailed(Throwable exception, String requestId) { + LOG.log(Level.SEVERE, "Elicitation handler or response delivery failed; cancelling the pending elicitation. " + + "SessionId=" + sessionId + ", RequestId=" + requestId, exception); + } + + private void logElicitationCancelDeliveryFailed(Throwable exception, String requestId) { + LOG.log(Level.WARNING, "Failed to deliver the elicitation cancellation back to the runtime. SessionId=" + + sessionId + ", RequestId=" + requestId, exception); + } + + private void logNoElicitationHandlerRegistered(String requestId) { + LOG.warning(() -> "Received an elicitation request without a registered elicitation handler. " + + "Another connected client may handle it; otherwise the elicitation request will never be answered " + + "by this client. SessionId=" + sessionId + ", RequestId=" + requestId); + } + + private void logMcpAuthFailed(Throwable exception, String requestId) { + LOG.log(Level.WARNING, "MCP OAuth request failed; cancelling the pending request. SessionId=" + sessionId + + ", RequestId=" + requestId, exception); + } + + private void logMcpAuthCancelDeliveryFailed(Throwable exception, String requestId) { + LOG.log(Level.WARNING, "Failed to deliver the MCP OAuth cancellation back to the runtime. SessionId=" + + sessionId + ", RequestId=" + requestId, exception); + } + /** * Executes a permission handler and sends the result back via * {@code session.permissions.handlePendingPermissionRequest}. @@ -1043,10 +1144,10 @@ private void executePermissionAndRespondAsync(String requestId, PermissionReques new SessionPermissionsHandlePendingPermissionRequestParams(sessionId, requestId, result, result.getDecisionContext())); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending permission result for requestId=" + requestId, e); + logPermissionFailed(e, requestId); } }).exceptionally(ex -> { - LOG.log(Level.SEVERE, "Permission handler failed for requestId=" + requestId, ex); + logPermissionFailed(unwrapCompletionException(ex), requestId); try { PermissionRequestResult denied = new PermissionRequestResult(); denied.setKind(PermissionRequestResultKind.DENIED_COULD_NOT_REQUEST_FROM_USER); @@ -1054,12 +1155,12 @@ private void executePermissionAndRespondAsync(String requestId, PermissionReques new SessionPermissionsHandlePendingPermissionRequestParams(sessionId, requestId, denied, null)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending permission denied for requestId=" + requestId, e); + logPermissionDecisionDeliveryFailed(e, requestId); } return null; }); } catch (Exception e) { - LOG.log(Level.WARNING, "Error executing permission handler for requestId=" + requestId, e); + logPermissionFailed(e, requestId); try { PermissionRequestResult denied = new PermissionRequestResult(); denied.setKind(PermissionRequestResultKind.DENIED_COULD_NOT_REQUEST_FROM_USER); @@ -1067,7 +1168,7 @@ private void executePermissionAndRespondAsync(String requestId, PermissionReques new SessionPermissionsHandlePendingPermissionRequestParams(sessionId, requestId, denied, null)); } catch (Exception sendEx) { - LOG.log(Level.WARNING, "Error sending permission denied for requestId=" + requestId, sendEx); + logPermissionDecisionDeliveryFailed(sendEx, requestId); } } }; @@ -1089,11 +1190,12 @@ private void executeMcpAuthAndRespondAsync(McpAuthRequest request, McpAuthHandle var invocation = new McpAuthInvocation().setSessionId(sessionId); handler.handle(request, invocation) .thenAccept(result -> sendMcpAuthResponse(request.requestId(), result)).exceptionally(ex -> { + logMcpAuthFailed(unwrapCompletionException(ex), request.requestId()); sendMcpAuthResponse(request.requestId(), McpAuthResult.cancelled()); return null; }); } catch (Exception e) { - LOG.log(Level.WARNING, "Error executing MCP auth handler for requestId=" + request.requestId(), e); + logMcpAuthFailed(e, request.requestId()); sendMcpAuthResponse(request.requestId(), McpAuthResult.cancelled()); } }; @@ -1111,11 +1213,13 @@ private void executeMcpAuthAndRespondAsync(McpAuthRequest request, McpAuthHandle } private void sendMcpAuthResponse(String requestId, McpAuthResult result) { + boolean isCancellationResponse = true; try { Object response; if (result == null || result.isCancelled() || result.token() == null) { response = Map.of("kind", "cancelled"); } else { + isCancellationResponse = false; var token = result.token(); var tokenResponse = new java.util.HashMap(); tokenResponse.put("kind", "token"); @@ -1131,7 +1235,12 @@ private void sendMcpAuthResponse(String requestId, McpAuthResult result) { getRpc().mcp.oauth.handlePendingRequest( new SessionMcpOauthHandlePendingRequestParams(sessionId, requestId, response)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending MCP auth response for requestId=" + requestId, e); + if (isCancellationResponse) { + logMcpAuthCancelDeliveryFailed(e, requestId); + } else { + LOG.log(Level.WARNING, + "Error sending MCP auth response. SessionId=" + sessionId + ", RequestId=" + requestId, e); + } } } @@ -1160,11 +1269,12 @@ private void executeCommandAndRespondAsync(String requestId, String commandName, CommandHandler handler = commandHandlers.get(commandName); Runnable task = () -> { if (handler == null) { + logNoCommandHandlerRegistered(requestId, commandName); try { getRpc().commands.handlePendingCommand(new SessionCommandsHandlePendingCommandParams(sessionId, requestId, "Unknown command: " + commandName)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending command error for requestId=" + requestId, e); + logCommandErrorDeliveryFailed(e, requestId, commandName); } return; } @@ -1176,26 +1286,27 @@ private void executeCommandAndRespondAsync(String requestId, String commandName, getRpc().commands.handlePendingCommand( new SessionCommandsHandlePendingCommandParams(sessionId, requestId, null)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending command result for requestId=" + requestId, e); + logCommandFailed(e, requestId, commandName); } }).exceptionally(ex -> { + logCommandFailed(unwrapCompletionException(ex), requestId, commandName); try { String msg = ex.getMessage() != null ? ex.getMessage() : ex.toString(); getRpc().commands.handlePendingCommand( new SessionCommandsHandlePendingCommandParams(sessionId, requestId, msg)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending command error for requestId=" + requestId, e); + logCommandErrorDeliveryFailed(e, requestId, commandName); } return null; }); } catch (Exception e) { - LOG.log(Level.WARNING, "Error executing command for requestId=" + requestId, e); + logCommandFailed(e, requestId, commandName); try { String msg = e.getMessage() != null ? e.getMessage() : e.toString(); getRpc().commands.handlePendingCommand( new SessionCommandsHandlePendingCommandParams(sessionId, requestId, msg)); } catch (Exception sendEx) { - LOG.log(Level.WARNING, "Error sending command error for requestId=" + requestId, sendEx); + logCommandErrorDeliveryFailed(sendEx, requestId, commandName); } } }; @@ -1218,6 +1329,7 @@ private void executeCommandAndRespondAsync(String requestId, String commandName, private void handleElicitationRequestAsync(ElicitationContext context, String requestId) { ElicitationHandler handler = elicitationHandler.get(); if (handler == null) { + logNoElicitationHandlerRegistered(requestId); return; } Runnable task = () -> { @@ -1232,22 +1344,24 @@ private void handleElicitationRequestAsync(ElicitationContext context, String re getRpc().ui.handlePendingElicitation( new SessionUiHandlePendingElicitationParams(sessionId, requestId, elicitationResult)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending elicitation result for requestId=" + requestId, e); + LOG.log(Level.SEVERE, "Elicitation response delivery failed. SessionId=" + sessionId + + ", RequestId=" + requestId, e); } }).exceptionally(ex -> { + logElicitationFailed(unwrapCompletionException(ex), requestId); try { getRpc().ui.handlePendingElicitation(buildElicitationCancelParams(requestId)); } catch (Exception e) { - LOG.log(Level.WARNING, "Error sending elicitation cancel for requestId=" + requestId, e); + logElicitationCancelDeliveryFailed(e, requestId); } return null; }); } catch (Exception e) { - LOG.log(Level.WARNING, "Error executing elicitation handler for requestId=" + requestId, e); + logElicitationFailed(e, requestId); try { getRpc().ui.handlePendingElicitation(buildElicitationCancelParams(requestId)); } catch (Exception sendEx) { - LOG.log(Level.WARNING, "Error sending elicitation cancel for requestId=" + requestId, sendEx); + logElicitationCancelDeliveryFailed(sendEx, requestId); } } }; diff --git a/nodejs/src/session.ts b/nodejs/src/session.ts index 65ff00921c..d6688222ae 100644 --- a/nodejs/src/session.ts +++ b/nodejs/src/session.ts @@ -382,6 +382,7 @@ function isFactoryFatalError(error: unknown): boolean { export type AssistantMessageEvent = Extract; const TOOL_SEARCH_TOOL_NAME = "tool_search_tool"; +type ToolDispatchStage = "InvokingHandler" | "ConvertingResult" | "SendingResult"; /** * Represents a single conversation session with the Copilot CLI. @@ -983,6 +984,14 @@ export class CopilotSession { traceparent, tracestate ); + } else { + console.warn("Received tool request without a registered tool handler", { + sessionId: this.sessionId, + requestId, + toolCallId, + toolName, + registeredToolNames: Array.from(this.toolHandlers.keys()), + }); } } else if (event.type === "permission.requested") { const { requestId, permissionRequest, resolvedByHook } = event.data as { @@ -995,6 +1004,14 @@ export class CopilotSession { } if (this.permissionHandler) { void this._executePermissionAndRespond(requestId, permissionRequest); + } else { + console.warn( + "Received permission request without a registered permission handler", + { + sessionId: this.sessionId, + requestId, + } + ); } } else if (event.type === "mcp.oauth_required") { const data = event.data as McpAuthRequest | undefined; @@ -1032,6 +1049,14 @@ export class CopilotSession { }, requestId ); + } else { + console.warn( + "Received elicitation request without a registered elicitation handler", + { + sessionId: this.sessionId, + requestId: event.data.requestId, + } + ); } } else if (event.type === "capabilities.changed") { this._capabilities = { ...this._capabilities, ...event.data }; @@ -1093,6 +1118,7 @@ export class CopilotSession { traceparent?: string, tracestate?: string ): Promise { + let stage: ToolDispatchStage = "InvokingHandler"; try { // The built-in tool-search tool receives a snapshot of the session's // currently initialized tools so an override can filter the live @@ -1117,6 +1143,7 @@ export class CopilotSession { traceparent, tracestate, }); + stage = "ConvertingResult"; let result: ToolResult; if (rawResult == null) { result = ""; @@ -1130,8 +1157,17 @@ export class CopilotSession { if (this.disconnected) { return; } + stage = "SendingResult"; await this.rpc.tools.handlePendingToolCall({ requestId, result }); } catch (error) { + console.error("Tool handler or response delivery failed", { + sessionId: this.sessionId, + requestId, + toolCallId, + toolName, + stage, + error, + }); if (this.disconnected) { return; } @@ -1142,7 +1178,13 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } - // Connection lost or RPC error — nothing we can do + console.warn("Failed to deliver tool handler error response", { + sessionId: this.sessionId, + requestId, + toolCallId, + toolName, + error: rpcError, + }); } } } @@ -1177,14 +1219,14 @@ export class CopilotSession { : { requestId, result, decisionContext } ); } catch (error) { - if (this.disconnected) { - return; - } console.error("Permission handler or response delivery failed", { sessionId: this.sessionId, requestId, error, }); + if (this.disconnected) { + return; + } try { await this.rpc.permissions.handlePendingPermissionRequest({ requestId, @@ -1196,7 +1238,11 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } - // Connection lost or RPC error — nothing we can do + console.warn("Failed to deliver permission handler fallback response", { + sessionId: this.sessionId, + requestId, + error: rpcError, + }); } } } @@ -1216,7 +1262,12 @@ export class CopilotSession { requestId: request.requestId, result: response, }); - } catch (_error) { + } catch (error) { + console.error("MCP OAuth handler or response delivery failed", { + sessionId: this.sessionId, + requestId: request.requestId, + error, + }); try { await this.rpc.mcp.oauth.handlePendingRequest({ requestId: request.requestId, @@ -1226,6 +1277,11 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } + console.warn("Failed to deliver MCP OAuth handler fallback response", { + sessionId: this.sessionId, + requestId: request.requestId, + error: rpcError, + }); } } } @@ -1242,6 +1298,12 @@ export class CopilotSession { ): Promise { const handler = this.commandHandlers.get(commandName); if (!handler) { + console.warn("Received command request without a registered command handler", { + sessionId: this.sessionId, + requestId, + commandName, + registeredCommandNames: Array.from(this.commandHandlers.keys()), + }); try { await this.rpc.commands.handlePendingCommand({ requestId, @@ -1251,6 +1313,12 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } + console.warn("Failed to deliver command handler error response", { + sessionId: this.sessionId, + requestId, + commandName, + error: rpcError, + }); } return; } @@ -1262,6 +1330,12 @@ export class CopilotSession { } await this.rpc.commands.handlePendingCommand({ requestId }); } catch (error) { + console.error("Command handler or response delivery failed", { + sessionId: this.sessionId, + requestId, + commandName, + error, + }); if (this.disconnected) { return; } @@ -1272,6 +1346,12 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } + console.warn("Failed to deliver command handler error response", { + sessionId: this.sessionId, + requestId, + commandName, + error: rpcError, + }); } } } @@ -1638,6 +1718,10 @@ export class CopilotSession { */ async _handleElicitationRequest(context: ElicitationContext, requestId: string): Promise { if (!this.elicitationHandler) { + console.warn("Received elicitation request without a registered elicitation handler", { + sessionId: this.sessionId, + requestId, + }); return; } try { @@ -1649,7 +1733,12 @@ export class CopilotSession { ...(result.content ? { content: result.content } : {}), }, }); - } catch { + } catch (error) { + console.error("Elicitation handler or response delivery failed", { + sessionId: this.sessionId, + requestId, + error, + }); // Handler failed — attempt to cancel so the request doesn't hang try { await this.rpc.ui.handlePendingElicitation({ @@ -1660,7 +1749,11 @@ export class CopilotSession { if (!(rpcError instanceof ConnectionError || rpcError instanceof ResponseError)) { throw rpcError; } - // Connection lost or RPC error — nothing we can do + console.warn("Failed to deliver elicitation handler fallback response", { + sessionId: this.sessionId, + requestId, + error: rpcError, + }); } } } diff --git a/nodejs/test/client.test.ts b/nodejs/test/client.test.ts index 3ffda2fa71..6e0d68f710 100644 --- a/nodejs/test/client.test.ts +++ b/nodejs/test/client.test.ts @@ -5,6 +5,7 @@ import { mkdtempSync } from "node:fs"; import { tmpdir } from "node:os"; import { join, resolve } from "node:path"; import { describe, expect, it, onTestFinished, vi } from "vitest"; +import { ErrorCodes, ResponseError } from "vscode-jsonrpc/node.js"; import { approveAll, createAttributedPermissionResult, @@ -348,6 +349,105 @@ describe("CopilotClient", () => { expect(observedRequest.wwwAuthenticateParams).toBeUndefined(); }); + it("logs MCP OAuth handler failures without logging request contents", async () => { + const handlerError = new Error("oauth failed"); + const sendRequest = vi.fn(async () => ({ success: true })); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); + const session = new CopilotSession( + "session-1", + { sendRequest } as any, + undefined, + undefined, + { + mcpAuthHandler: async () => { + throw handlerError; + }, + } + ); + + await (session as any)._executeMcpAuthAndRespond({ + requestId: "oauth-request", + serverName: "sensitive-server", + serverUrl: "https://example.com/mcp", + reason: "initial", + }); + + expect(error).toHaveBeenCalledWith("MCP OAuth handler or response delivery failed", { + sessionId: "session-1", + requestId: "oauth-request", + error: handlerError, + }); + expect(JSON.stringify(error.mock.calls)).not.toContain("sensitive-server"); + expect(sendRequest).toHaveBeenCalledWith("session.mcp.oauth.handlePendingRequest", { + sessionId: "session-1", + requestId: "oauth-request", + result: { kind: "cancelled" }, + }); + error.mockRestore(); + }); + + it("logs permission requests without a registered handler", () => { + const session = new CopilotSession("session-1", { + sendRequest: vi.fn(async () => ({ success: true })), + } as any); + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); + + (session as any)._dispatchEvent({ + id: "evt-permission-missing", + timestamp: new Date().toISOString(), + parentId: null, + ephemeral: true, + type: "permission.requested", + data: { + requestId: "req-permission-missing", + permissionRequest: { kind: "shell", commands: ["echo do-not-log"] }, + }, + }); + + expect(warn).toHaveBeenCalledWith( + "Received permission request without a registered permission handler", + { + sessionId: "session-1", + requestId: "req-permission-missing", + } + ); + expect(JSON.stringify(warn.mock.calls)).not.toContain("do-not-log"); + warn.mockRestore(); + }); + + it("logs permission handler failures without logging request contents", async () => { + const handlerError = new Error("permission failed"); + const sendRequest = vi.fn(async () => ({ success: true })); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); + const session = new CopilotSession("session-1", { sendRequest } as any); + session.registerPermissionHandler(() => { + throw handlerError; + }); + + await (session as any)._executePermissionAndRespond("req-permission-failed", { + kind: "shell", + commands: ["echo do-not-log"], + }); + + expect(error).toHaveBeenCalledWith("Permission handler or response delivery failed", { + sessionId: "session-1", + requestId: "req-permission-failed", + error: handlerError, + }); + expect(JSON.stringify(error.mock.calls)).not.toContain("do-not-log"); + expect(sendRequest).toHaveBeenCalledWith( + "session.permissions.handlePendingPermissionRequest", + { + sessionId: "session-1", + requestId: "req-permission-failed", + result: { + kind: "user-not-available", + }, + } + ); + error.mockRestore(); + }); + it("registers interest in MCP OAuth required events after create when an auth handler is configured", async () => { const client = new CopilotClient(); await client.start(); @@ -1002,6 +1102,141 @@ describe("CopilotClient", () => { expect(createPayload.tools[0].isTerminal).toBeUndefined(); }); + it("logs external tool requests without a registered handler", () => { + const session = new CopilotSession("session-1", { + sendRequest: vi.fn(async () => ({ success: true })), + } as any); + const registeredHandler = vi.fn(); + session.registerTools([{ name: "registered_tool", handler: registeredHandler }]); + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); + + (session as any)._dispatchEvent({ + id: "evt-tool-missing", + timestamp: new Date().toISOString(), + parentId: null, + ephemeral: true, + type: "external_tool.requested", + data: { + requestId: "req-tool-missing", + toolName: "missing_tool", + toolCallId: "call-1", + arguments: { secret: "do-not-log" }, + sessionId: "session-1", + }, + }); + + expect(warn).toHaveBeenCalledWith( + "Received tool request without a registered tool handler", + { + sessionId: "session-1", + requestId: "req-tool-missing", + toolCallId: "call-1", + toolName: "missing_tool", + registeredToolNames: ["registered_tool"], + } + ); + expect(JSON.stringify(warn.mock.calls)).not.toContain("do-not-log"); + expect(registeredHandler).not.toHaveBeenCalled(); + warn.mockRestore(); + }); + + it("logs external tool handler failures with dispatch stage", async () => { + const handlerError = new Error("tool failed"); + const sendRequest = vi.fn(async () => ({ success: true })); + const session = new CopilotSession("session-1", { sendRequest } as any); + session.registerTools([ + { + name: "failing_tool", + handler: () => { + throw handlerError; + }, + }, + ]); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); + + (session as any)._dispatchEvent({ + id: "evt-tool-failed", + timestamp: new Date().toISOString(), + parentId: null, + ephemeral: true, + type: "external_tool.requested", + data: { + requestId: "req-tool-failed", + toolName: "failing_tool", + toolCallId: "call-2", + arguments: { secret: "do-not-log" }, + sessionId: "session-1", + }, + }); + + await vi.waitFor(() => + expect(sendRequest).toHaveBeenCalledWith("session.tools.handlePendingToolCall", { + sessionId: "session-1", + requestId: "req-tool-failed", + error: "tool failed", + }) + ); + expect(error).toHaveBeenCalledWith("Tool handler or response delivery failed", { + sessionId: "session-1", + requestId: "req-tool-failed", + toolCallId: "call-2", + toolName: "failing_tool", + stage: "InvokingHandler", + error: handlerError, + }); + expect(JSON.stringify(error.mock.calls)).not.toContain("do-not-log"); + error.mockRestore(); + }); + + it("logs external tool response delivery failures with dispatch stage", async () => { + const rpcError = new ResponseError(ErrorCodes.InternalError, "rpc failed"); + const sendRequest = vi.fn(async () => { + throw rpcError; + }); + const session = new CopilotSession("session-1", { sendRequest } as any); + session.registerTools([{ name: "echo_tool", handler: () => "ok" }]); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); + + (session as any)._dispatchEvent({ + id: "evt-tool-rpc-failed", + timestamp: new Date().toISOString(), + parentId: null, + ephemeral: true, + type: "external_tool.requested", + data: { + requestId: "req-tool-rpc-failed", + toolName: "echo_tool", + toolCallId: "call-3", + arguments: { secret: "do-not-log" }, + sessionId: "session-1", + }, + }); + + await vi.waitFor(() => + expect(warn).toHaveBeenCalledWith("Failed to deliver tool handler error response", { + sessionId: "session-1", + requestId: "req-tool-rpc-failed", + toolCallId: "call-3", + toolName: "echo_tool", + error: rpcError, + }) + ); + expect(error).toHaveBeenCalledWith("Tool handler or response delivery failed", { + sessionId: "session-1", + requestId: "req-tool-rpc-failed", + toolCallId: "call-3", + toolName: "echo_tool", + stage: "SendingResult", + error: rpcError, + }); + expect(JSON.stringify([...error.mock.calls, ...warn.mock.calls])).not.toContain( + "do-not-log" + ); + error.mockRestore(); + warn.mockRestore(); + }); + it("forwards new session options in session.create and session.resume", async () => { const client = new CopilotClient(); await client.start(); @@ -3334,13 +3569,15 @@ describe("CopilotClient", () => { await client.start(); onTestFinished(() => stopClient(client)); + const handlerError = new Error("deploy failed"); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); const session = await client.createSession({ onPermissionRequest: approveAll, commands: [ { name: "fail", handler: () => { - throw new Error("deploy failed"); + throw handlerError; }, }, ], @@ -3374,7 +3611,14 @@ describe("CopilotClient", () => { expect.objectContaining({ requestId: "req-2", error: "deploy failed" }) ) ); + expect(error).toHaveBeenCalledWith("Command handler or response delivery failed", { + sessionId: session.sessionId, + requestId: "req-2", + commandName: "fail", + error: handlerError, + }); rpcSpy.mockRestore(); + error.mockRestore(); }); it("sends error for unknown command", async () => { @@ -3382,6 +3626,7 @@ describe("CopilotClient", () => { await client.start(); onTestFinished(() => stopClient(client)); + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); const session = await client.createSession({ onPermissionRequest: approveAll, commands: [{ name: "deploy", handler: async () => {} }], @@ -3418,7 +3663,17 @@ describe("CopilotClient", () => { }) ) ); + expect(warn).toHaveBeenCalledWith( + "Received command request without a registered command handler", + { + sessionId: session.sessionId, + requestId: "req-3", + commandName: "unknown", + registeredCommandNames: ["deploy"], + } + ); rpcSpy.mockRestore(); + warn.mockRestore(); }); }); @@ -3526,6 +3781,36 @@ describe("CopilotClient", () => { rpcSpy.mockRestore(); }); + it("logs elicitation requests without a registered handler", () => { + const session = new CopilotSession("session-1", { + sendRequest: vi.fn(async () => ({ success: true })), + } as any); + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); + + (session as any)._dispatchEvent({ + id: "evt-elicitation-missing", + timestamp: new Date().toISOString(), + parentId: null, + ephemeral: true, + type: "elicitation.requested", + data: { + requestId: "req-elicitation-missing", + message: "do-not-log", + requestedSchema: { type: "object" }, + }, + }); + + expect(warn).toHaveBeenCalledWith( + "Received elicitation request without a registered elicitation handler", + { + sessionId: "session-1", + requestId: "req-elicitation-missing", + } + ); + expect(JSON.stringify(warn.mock.calls)).not.toContain("do-not-log"); + warn.mockRestore(); + }); + it("sends mode callback request flags based on handler presence", async () => { const client = new CopilotClient(); await client.start(); @@ -3614,10 +3899,12 @@ describe("CopilotClient", () => { await client.start(); onTestFinished(() => stopClient(client)); + const handlerError = new Error("handler exploded"); + const error = vi.spyOn(console, "error").mockImplementation(() => {}); const session = await client.createSession({ onPermissionRequest: approveAll, onElicitationRequest: async () => { - throw new Error("handler exploded"); + throw handlerError; }, }); @@ -3640,7 +3927,13 @@ describe("CopilotClient", () => { result: { action: "cancel" }, }) ); + expect(error).toHaveBeenCalledWith("Elicitation handler or response delivery failed", { + sessionId: session.sessionId, + requestId: "req-123", + error: handlerError, + }); rpcSpy.mockRestore(); + error.mockRestore(); }); }); diff --git a/python/copilot/session.py b/python/copilot/session.py index 78afdde139..9a79388ff8 100644 --- a/python/copilot/session.py +++ b/python/copilot/session.py @@ -1937,6 +1937,25 @@ def _handle_broadcast_event(self, event: SessionEvent) -> None: handler = self._get_tool_handler(tool_name) if not handler: + if logger.isEnabledFor(logging.WARNING): + with self._tool_handlers_lock: + registered_tools = ", ".join(self._tool_handlers.keys()) + logger.warning( + "Received a tool request for a tool this client has no handler " + "registered for. Another connected client may handle it; otherwise " + "the tool call will never be answered by this client. " + "SessionId=%s, RequestId=%s, Tool=%s, RegisteredTools=[%s]", + self.session_id, + request_id, + tool_name, + registered_tools, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "tool_name": tool_name, + "registered_tools": registered_tools, + }, + ) return # This client doesn't handle this tool; another client will. tool_call_id = data.tool_call_id or "" @@ -1970,6 +1989,14 @@ def _handle_broadcast_event(self, event: SessionEvent) -> None: with self._permission_handler_lock: perm_handler = self._permission_handler if not perm_handler: + logger.warning( + "Received a permission request without a registered permission handler. " + "Another connected client may handle it; otherwise the permission request " + "will never be answered by this client. SessionId=%s, RequestId=%s", + self.session_id, + request_id, + extra={"session_id": self.session_id, "request_id": request_id}, + ) return # This client doesn't handle permissions; another client will. asyncio.ensure_future( @@ -1989,6 +2016,7 @@ def _handle_broadcast_event(self, event: SessionEvent) -> None: "SessionId=%s, RequestId=%s", self.session_id, data.request_id, + extra={"session_id": self.session_id, "request_id": data.request_id}, ) return request: McpAuthRequest = { @@ -2044,12 +2072,19 @@ def _handle_broadcast_event(self, event: SessionEvent) -> None: ) case ElicitationRequestedData() as data: + request_id = data.request_id + if not request_id: + return with self._elicitation_handler_lock: handler = self._elicitation_handler if not handler: - return - request_id = data.request_id - if not request_id: + logger.warning( + "Received an elicitation request without a registered elicitation handler. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + extra={"session_id": self.session_id, "request_id": request_id}, + ) return context: ElicitationContext = { "session_id": self.session_id, @@ -2101,6 +2136,7 @@ async def _execute_tool_and_respond( tracestate: str | None = None, ) -> None: """Execute a tool handler and send the result back via HandlePendingToolCall RPC.""" + stage = "PreparingArguments" try: # The built-in tool-search tool receives a snapshot of the session's # currently initialized tools so an override can filter the live @@ -2125,6 +2161,7 @@ async def _execute_tool_and_respond( with trace_context(traceparent, tracestate): handler_start = time.perf_counter() + stage = "InvokingHandler" result = handler(invocation) if inspect.isawaitable(result): result = await result @@ -2139,6 +2176,7 @@ async def _execute_tool_and_respond( tool_name=tool_name, ) + stage = "ConvertingResult" tool_result: ToolResult if result is None: tool_result = ToolResult( @@ -2155,7 +2193,30 @@ async def _execute_tool_and_respond( # standard "Failed to execute..." message. Deliberate user-returned # failures send the full structured result to preserve metadata. if tool_result._from_exception: + if tool_result._exception is not None: + logger.error( + "Tool call failed. Stage=%s, SessionId=%s, RequestId=%s, " + "ToolCallId=%s, Tool=%s", + "InvokingHandler", + self.session_id, + request_id, + tool_call_id, + tool_name, + exc_info=( + type(tool_result._exception), + tool_result._exception, + tool_result._exception.__traceback__, + ), + extra={ + "stage": "InvokingHandler", + "session_id": self.session_id, + "request_id": request_id, + "tool_call_id": tool_call_id, + "tool_name": tool_name, + }, + ) rpc_start = time.perf_counter() + stage = "SendingResult" await self.rpc.tools.handle_pending_tool_call( HandlePendingToolCallRequest( request_id=request_id, @@ -2173,11 +2234,13 @@ async def _execute_tool_and_respond( tool_name=tool_name, ) else: + result_for_llm = tool_result_to_external_tool_text_result_for_llm(tool_result) rpc_start = time.perf_counter() + stage = "SendingResult" await self.rpc.tools.handle_pending_tool_call( HandlePendingToolCallRequest( request_id=request_id, - result=tool_result_to_external_tool_text_result_for_llm(tool_result), + result=result_for_llm, ) ) log_timing( @@ -2191,6 +2254,21 @@ async def _execute_tool_and_respond( tool_name=tool_name, ) except Exception as exc: + logger.exception( + "Tool call failed. Stage=%s, SessionId=%s, RequestId=%s, ToolCallId=%s, Tool=%s", + stage, + self.session_id, + request_id, + tool_call_id, + tool_name, + extra={ + "stage": stage, + "session_id": self.session_id, + "request_id": request_id, + "tool_call_id": tool_call_id, + "tool_name": tool_name, + }, + ) try: await self.rpc.tools.handle_pending_tool_call( HandlePendingToolCallRequest( @@ -2199,7 +2277,19 @@ async def _execute_tool_and_respond( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost or RPC error — nothing we can do + logger.warning( + "Failed to deliver the tool call error back to the runtime. " + "SessionId=%s, RequestId=%s, Tool=%s", + self.session_id, + request_id, + tool_name, + exc_info=True, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "tool_name": tool_name, + }, + ) async def _execute_permission_and_respond( self, @@ -2254,7 +2344,9 @@ async def _execute_permission_and_respond( ) except Exception: logger.exception( - "Permission handler or response delivery failed", + "Permission handler or response delivery failed. SessionId=%s, RequestId=%s", + self.session_id, + request_id, extra={"session_id": self.session_id, "request_id": request_id}, ) try: @@ -2265,7 +2357,14 @@ async def _execute_permission_and_respond( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost or RPC error — nothing we can do + logger.warning( + "Failed to deliver the permission decision back to the runtime. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + exc_info=True, + extra={"session_id": self.session_id, "request_id": request_id}, + ) async def _execute_mcp_auth_and_respond( self, @@ -2308,6 +2407,14 @@ async def _execute_mcp_auth_and_respond( ) ) except Exception: + logger.warning( + "MCP OAuth request failed; cancelling the pending request. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + exc_info=True, + extra={"session_id": self.session_id, "request_id": request_id}, + ) try: await self.rpc.mcp.oauth.handle_pending_request( MCPOauthHandlePendingRequest( @@ -2318,7 +2425,14 @@ async def _execute_mcp_auth_and_respond( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost or RPC error — nothing we can do + logger.warning( + "Failed to deliver the MCP OAuth cancellation back to the runtime. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + exc_info=True, + extra={"session_id": self.session_id, "request_id": request_id}, + ) async def _execute_command_and_respond( self, @@ -2332,6 +2446,24 @@ async def _execute_command_and_respond( handler = self._command_handlers.get(command_name) if not handler: + if logger.isEnabledFor(logging.WARNING): + with self._command_handlers_lock: + registered_commands = ", ".join(self._command_handlers.keys()) + logger.warning( + "Received a command request for a command this client has no handler " + "registered for. SessionId=%s, RequestId=%s, Command=%s, " + "RegisteredCommands=[%s]", + self.session_id, + request_id, + command_name, + registered_commands, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "command_name": command_name, + "registered_commands": registered_commands, + }, + ) try: await self.rpc.commands.handle_pending_command( CommandsHandlePendingCommandRequest( @@ -2340,7 +2472,19 @@ async def _execute_command_and_respond( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost — nothing we can do + logger.warning( + "Failed to deliver the command error back to the runtime. " + "SessionId=%s, RequestId=%s, Command=%s", + self.session_id, + request_id, + command_name, + exc_info=True, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "command_name": command_name, + }, + ) return try: @@ -2377,6 +2521,18 @@ async def _execute_command_and_respond( command_name=command_name, ) except Exception as exc: + logger.exception( + "Command handler or response delivery failed. " + "SessionId=%s, RequestId=%s, Command=%s", + self.session_id, + request_id, + command_name, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "command_name": command_name, + }, + ) message = str(exc) try: await self.rpc.commands.handle_pending_command( @@ -2386,7 +2542,19 @@ async def _execute_command_and_respond( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost — nothing we can do + logger.warning( + "Failed to deliver the command error back to the runtime. " + "SessionId=%s, RequestId=%s, Command=%s", + self.session_id, + request_id, + command_name, + exc_info=True, + extra={ + "session_id": self.session_id, + "request_id": request_id, + "command_name": command_name, + }, + ) async def _handle_elicitation_request( self, @@ -2401,6 +2569,13 @@ async def _handle_elicitation_request( with self._elicitation_handler_lock: handler = self._elicitation_handler if not handler: + logger.warning( + "Received an elicitation request without a registered elicitation handler. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + extra={"session_id": self.session_id, "request_id": request_id}, + ) return try: handler_start = time.perf_counter() @@ -2438,6 +2613,13 @@ async def _handle_elicitation_request( ) except Exception: # Handler failed — attempt to cancel so the request doesn't hang + logger.exception( + "Elicitation handler or response delivery failed; cancelling the pending " + "elicitation. SessionId=%s, RequestId=%s", + self.session_id, + request_id, + extra={"session_id": self.session_id, "request_id": request_id}, + ) try: await self.rpc.ui.handle_pending_elicitation( UIHandlePendingElicitationRequest( @@ -2448,7 +2630,14 @@ async def _handle_elicitation_request( ) ) except (JsonRpcError, ProcessExitedError, OSError): - pass # Connection lost or RPC error — nothing we can do + logger.warning( + "Failed to deliver the elicitation cancellation back to the runtime. " + "SessionId=%s, RequestId=%s", + self.session_id, + request_id, + exc_info=True, + extra={"session_id": self.session_id, "request_id": request_id}, + ) def _assert_elicitation(self) -> None: """Raises if the host does not support elicitation.""" diff --git a/python/copilot/tools.py b/python/copilot/tools.py index ad0bcb41bd..b7e62e5395 100644 --- a/python/copilot/tools.py +++ b/python/copilot/tools.py @@ -53,6 +53,7 @@ class ToolResult: tool_telemetry: dict[str, Any] | None = None tool_references: list[str] | None = None _from_exception: bool = field(default=False, repr=False) + _exception: BaseException | None = field(default=None, repr=False) @dataclass @@ -294,6 +295,7 @@ async def wrapped_handler(invocation: ToolInvocation) -> ToolResult: error=str(exc), tool_telemetry={}, _from_exception=True, + _exception=exc, ) return Tool( diff --git a/python/test_session.py b/python/test_session.py index dd2d0a72f6..1d262aadd9 100644 --- a/python/test_session.py +++ b/python/test_session.py @@ -1,20 +1,26 @@ """CopilotSession unit tests.""" import asyncio +import logging from datetime import UTC, datetime -from unittest.mock import AsyncMock, Mock +from unittest.mock import AsyncMock, MagicMock, Mock from uuid import uuid4 import pytest -from copilot.session import CopilotSession +from copilot.session import CommandDefinition, CopilotSession, McpAuthRequest from copilot.session_events import ( AssistantMessageData, + ElicitationRequestedData, + ExternalToolRequestedData, + PermissionRequestedData, + PermissionRequestRead, SessionEvent, SessionEventType, SessionIdleData, SessionMode, ) +from copilot.tools import Tool, define_tool def _event(data, event_type: SessionEventType) -> SessionEvent: @@ -26,6 +32,22 @@ def _event(data, event_type: SessionEventType) -> SessionEvent: ) +def _session_with_mock_rpc() -> tuple[CopilotSession, MagicMock]: + session = CopilotSession("session-1", client=None) + rpc = MagicMock() + rpc.tools.handle_pending_tool_call = AsyncMock() + rpc.permissions.handle_pending_permission_request = AsyncMock() + rpc.mcp.oauth.handle_pending_request = AsyncMock() + rpc.commands.handle_pending_command = AsyncMock() + rpc.ui.handle_pending_elicitation = AsyncMock() + session._rpc = rpc + return session, rpc + + +def _log_field(record: logging.LogRecord, name: str) -> object: + return record.__dict__[name] + + @pytest.mark.asyncio async def test_send_and_wait_skips_autopilot_continuation_idle(): client = Mock() @@ -67,3 +89,262 @@ async def test_send_and_wait_skips_autopilot_continuation_idle(): assert result is not None assert isinstance(result.data, AssistantMessageData) assert result.data.content == "final" + + +@pytest.mark.asyncio +async def test_tool_handler_failure_logs_stage_and_reports_rpc_error( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + caplog.set_level(logging.ERROR, logger="copilot.session") + + def handler(_invocation): + raise RuntimeError("handler exploded") + + await session._execute_tool_and_respond( + "request-1", + "failing_tool", + "tool-call-1", + {"token": "top-secret"}, + handler, + ) + + sent = rpc.tools.handle_pending_tool_call.await_args.args[0].to_dict() + assert sent == {"requestId": "request-1", "error": "handler exploded"} + record = next(record for record in caplog.records if "Tool call failed" in record.message) + assert record.levelno == logging.ERROR + assert record.exc_info is not None + assert _log_field(record, "stage") == "InvokingHandler" + assert _log_field(record, "session_id") == "session-1" + assert _log_field(record, "request_id") == "request-1" + assert _log_field(record, "tool_call_id") == "tool-call-1" + assert _log_field(record, "tool_name") == "failing_tool" + assert "top-secret" not in caplog.text + + +@pytest.mark.asyncio +async def test_define_tool_exception_logs_original_traceback( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + caplog.set_level(logging.ERROR, logger="copilot.session") + + def handler() -> str: + raise RuntimeError("decorated handler exploded") + + tool_factory = define_tool("decorated_tool") + tool = tool_factory(handler) + assert isinstance(tool, Tool) + assert tool.handler is not None + + await session._execute_tool_and_respond( + "request-1", "decorated_tool", "tool-call-1", {}, tool.handler + ) + + sent = rpc.tools.handle_pending_tool_call.await_args.args[0].to_dict() + assert sent == {"requestId": "request-1", "error": "decorated handler exploded"} + record = next(record for record in caplog.records if "Tool call failed" in record.message) + assert record.levelno == logging.ERROR + assert record.exc_info is not None + assert record.exc_info[0] is RuntimeError + assert _log_field(record, "stage") == "InvokingHandler" + + +def test_missing_tool_handler_logs_registered_tools_without_arguments( + caplog: pytest.LogCaptureFixture, +) -> None: + session, _rpc = _session_with_mock_rpc() + session._register_tools([Tool(name="known_tool", description="", handler=lambda _inv: None)]) + caplog.set_level(logging.WARNING, logger="copilot.session") + + session._dispatch_event( + _event( + ExternalToolRequestedData( + request_id="request-1", + session_id="session-1", + tool_call_id="tool-call-1", + tool_name="missing_tool", + arguments={"token": "top-secret"}, + ), + SessionEventType.EXTERNAL_TOOL_REQUESTED, + ) + ) + + record = next(record for record in caplog.records if "no handler registered" in record.message) + assert record.levelno == logging.WARNING + assert _log_field(record, "session_id") == "session-1" + assert _log_field(record, "request_id") == "request-1" + assert _log_field(record, "tool_name") == "missing_tool" + assert _log_field(record, "registered_tools") == "known_tool" + assert "top-secret" not in caplog.text + + +def test_missing_permission_handler_logs_without_request_contents( + caplog: pytest.LogCaptureFixture, +) -> None: + session, _rpc = _session_with_mock_rpc() + caplog.set_level(logging.WARNING, logger="copilot.session") + + session._dispatch_event( + _event( + PermissionRequestedData( + request_id="permission-1", + permission_request=PermissionRequestRead( + intention="read sensitive file", + path="sensitive-file.txt", + ), + ), + SessionEventType.PERMISSION_REQUESTED, + ) + ) + + record = next( + record for record in caplog.records if "registered permission handler" in record.message + ) + assert record.levelno == logging.WARNING + assert _log_field(record, "session_id") == "session-1" + assert _log_field(record, "request_id") == "permission-1" + assert "sensitive-file.txt" not in caplog.text + + +@pytest.mark.asyncio +async def test_command_handler_and_error_delivery_failures_are_logged( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + rpc.commands.handle_pending_command.side_effect = OSError("connection gone") + session._register_commands( + [ + CommandDefinition( + name="deploy", + handler=lambda _ctx: (_ for _ in ()).throw(RuntimeError("deploy failed")), + ) + ] + ) + caplog.set_level(logging.WARNING, logger="copilot.session") + + await session._execute_command_and_respond("command-1", "deploy", "/deploy prod", "prod") + + assert any( + record.levelno == logging.ERROR + and "Command handler or response delivery failed" in record.message + and _log_field(record, "command_name") == "deploy" + for record in caplog.records + ) + assert any( + record.levelno == logging.WARNING + and "Failed to deliver the command error back to the runtime" in record.message + and _log_field(record, "command_name") == "deploy" + for record in caplog.records + ) + assert "/deploy prod" not in caplog.text + + +@pytest.mark.asyncio +async def test_missing_command_handler_logs_registered_commands_without_command_text( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + session._register_commands([CommandDefinition(name="known", handler=lambda _ctx: None)]) + caplog.set_level(logging.WARNING, logger="copilot.session") + + await session._execute_command_and_respond( + "command-1", "missing", "/missing secret-args", "secret-args" + ) + + sent = rpc.commands.handle_pending_command.await_args.args[0].to_dict() + assert sent == {"requestId": "command-1", "error": "Unknown command: missing"} + record = next( + record + for record in caplog.records + if "command this client has no handler registered" in record.message + ) + assert record.levelno == logging.WARNING + assert _log_field(record, "command_name") == "missing" + assert _log_field(record, "registered_commands") == "known" + assert "secret-args" not in caplog.text + + +@pytest.mark.asyncio +async def test_elicitation_failure_and_cancellation_delivery_failure_are_logged( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + rpc.ui.handle_pending_elicitation.side_effect = OSError("connection gone") + session._register_elicitation_handler( + lambda _ctx: (_ for _ in ()).throw(RuntimeError("elicitation failed")) + ) + caplog.set_level(logging.WARNING, logger="copilot.session") + + await session._handle_elicitation_request( + {"session_id": "session-1", "message": "secret prompt"}, "elicitation-1" + ) + + assert any( + record.levelno == logging.ERROR + and "Elicitation handler or response delivery failed" in record.message + for record in caplog.records + ) + assert any( + record.levelno == logging.WARNING + and "Failed to deliver the elicitation cancellation back to the runtime" in record.message + for record in caplog.records + ) + assert "secret prompt" not in caplog.text + + +@pytest.mark.asyncio +async def test_mcp_oauth_failure_and_cancellation_delivery_failure_are_logged( + caplog: pytest.LogCaptureFixture, +) -> None: + session, rpc = _session_with_mock_rpc() + rpc.mcp.oauth.handle_pending_request.side_effect = OSError("connection gone") + caplog.set_level(logging.WARNING, logger="copilot.session") + + request: McpAuthRequest = { + "requestId": "mcp-1", + "serverName": "sensitive-server", + "serverUrl": "https://sensitive.example", + "reason": "initial", + } + await session._execute_mcp_auth_and_respond( + request, lambda _request, _ctx: (_ for _ in ()).throw(RuntimeError("MCP auth failed")) + ) + + assert any( + record.levelno == logging.WARNING + and "MCP OAuth request failed; cancelling the pending request" in record.message + for record in caplog.records + ) + assert any( + record.levelno == logging.WARNING + and "Failed to deliver the MCP OAuth cancellation back to the runtime" in record.message + for record in caplog.records + ) + assert "sensitive-server" not in caplog.text + assert "https://sensitive.example" not in caplog.text + + +def test_missing_elicitation_handler_logs_request_id_without_contents( + caplog: pytest.LogCaptureFixture, +) -> None: + session, _rpc = _session_with_mock_rpc() + caplog.set_level(logging.WARNING, logger="copilot.session") + + session._dispatch_event( + _event( + ElicitationRequestedData( + request_id="elicitation-1", + message="secret prompt", + ), + SessionEventType.ELICITATION_REQUESTED, + ) + ) + + record = next( + record for record in caplog.records if "registered elicitation handler" in record.message + ) + assert record.levelno == logging.WARNING + assert _log_field(record, "session_id") == "session-1" + assert _log_field(record, "request_id") == "elicitation-1" + assert "secret prompt" not in caplog.text diff --git a/rust/src/session.rs b/rust/src/session.rs index b9d2173055..1f293fca81 100644 --- a/rust/src/session.rs +++ b/rust/src/session.rs @@ -8,7 +8,7 @@ use serde_json::Value; use tokio::sync::oneshot; use tokio::task::JoinHandle; use tokio_util::sync::CancellationToken; -use tracing::{Instrument, warn}; +use tracing::{Instrument, error, warn}; use crate::canvas::CanvasHandler; use crate::generated::api_types::{ @@ -1495,6 +1495,12 @@ fn build_command_handler_map(commands: Option<&[CommandDefinition]>) -> Arc(handlers: &HashMap) -> String { + let mut names = handlers.keys().map(String::as_str).collect::>(); + names.sort_unstable(); + names.join(", ") +} + fn upsert_open_canvas_snapshot( snapshots: &mut Vec, snapshot: OpenCanvasInstance, @@ -1852,6 +1858,11 @@ async fn handle_notification( // handler installed, don't respond — another client on the // same CLI may handle it. let Some(permission_handler) = handlers.permission.clone() else { + warn!( + session_id = %session_id, + request_id = %request_id, + "received permission request without a registered permission handler" + ); return; }; let client = client.clone(); @@ -1885,18 +1896,26 @@ async fn handle_notification( return; }; let rpc_start = Instant::now(); - let _ = client + let response = client .call( rpc_methods::SESSION_PERMISSIONS_HANDLEPENDINGPERMISSIONREQUEST, Some(params), ) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - session_id = %sid, - request_id = %request_id, - "Session::handle_notification response sent successfully" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + "Session::handle_notification response sent successfully" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + "failed to deliver permission decision back to the runtime" + ), + } } .instrument(span), ); @@ -1909,7 +1928,29 @@ async fn handle_notification( match serde_json::from_value(notification.event.data.clone()) { Ok(d) => d, Err(e) => { - warn!(error = %e, "failed to deserialize external_tool.requested"); + let tool_call_id = notification + .event + .data + .get("toolCallId") + .and_then(Value::as_str) + .unwrap_or("") + .to_string(); + let tool_name = notification + .event + .data + .get("toolName") + .and_then(Value::as_str) + .unwrap_or("") + .to_string(); + error!( + error = %e, + session_id = %session_id, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + stage = "PreparingArguments", + "tool call failed" + ); let client = client.clone(); let sid = session_id.clone(); let span = tracing::error_span!( @@ -1920,7 +1961,7 @@ async fn handle_notification( tokio::spawn( async move { let rpc_start = Instant::now(); - let _ = client + let response = client .call( "session.tools.handlePendingToolCall", Some(serde_json::json!({ @@ -1930,12 +1971,22 @@ async fn handle_notification( })), ) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - session_id = %sid, - request_id = %request_id, - "Session::handle_notification response sent successfully" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + "Session::handle_notification response sent successfully" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + "failed to deliver tool call error back to the runtime" + ), + } } .instrument(span), ); @@ -1951,6 +2002,16 @@ async fn handle_notification( handlers.tools.get(&data.tool_name).cloned() }; let Some(tool_handler) = tool_handler else { + if tracing::enabled!(tracing::Level::WARN) { + let registered_tool_names = registered_names(handlers.tools.as_ref()); + warn!( + session_id = %session_id, + request_id = %request_id, + tool_name = %data.tool_name, + registered_tool_names = %registered_tool_names, + "received tool request without a registered tool handler" + ); + } return; }; let client = client.clone(); @@ -1962,14 +2023,24 @@ async fn handle_notification( ); tokio::spawn( async move { + let tool_name = data.tool_name.clone(); // `tool_name.is_empty()` would have produced a `None` // lookup in `handlers.tools` and short-circuited at the // outer guard above, so only the tool_call_id check is // reachable here. if data.tool_call_id.is_empty() { let error_msg = "Missing toolCallId"; + error!( + error = %error_msg, + session_id = %sid, + request_id = %request_id, + tool_call_id = %data.tool_call_id, + tool_name = %tool_name, + stage = "PreparingArguments", + "tool call failed" + ); let rpc_start = Instant::now(); - let _ = client + let response = client .call( "session.tools.handlePendingToolCall", Some(serde_json::json!({ @@ -1979,16 +2050,25 @@ async fn handle_notification( })), ) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - session_id = %sid, - request_id = %request_id, - "Session::handle_notification response sent successfully" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + "Session::handle_notification response sent successfully" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %data.tool_call_id, + tool_name = %tool_name, + "failed to deliver tool call error back to the runtime" + ), + } return; } let tool_call_id = data.tool_call_id.clone(); - let tool_name = data.tool_name.clone(); // The built-in tool-search tool receives a snapshot of the // session's currently initialized tools so an override can // filter the live catalog without issuing its own RPC. Fetch @@ -2025,9 +2105,21 @@ async fn handle_notification( tracestate: data.tracestate, }; let handler_start = Instant::now(); - let tool_result = match tool_handler.call(invocation).await { - Ok(r) => r, - Err(e) => tool_failure_result(e.to_string()), + let (tool_result, handler_succeeded) = match tool_handler.call(invocation).await + { + Ok(r) => (r, true), + Err(e) => { + error!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + stage = "InvokingHandler", + "tool call failed" + ); + (tool_failure_result(e.to_string()), false) + } }; tracing::debug!( elapsed_ms = handler_start.elapsed().as_millis(), @@ -2037,9 +2129,23 @@ async fn handle_notification( tool_name = %tool_name, "ToolHandler::call dispatch" ); - let result_value = serde_json::to_value(tool_result).unwrap_or(Value::Null); + let (result_value, result_converted) = match serde_json::to_value(tool_result) { + Ok(value) => (value, true), + Err(e) => { + error!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + stage = "ConvertingResult", + "tool call failed" + ); + (Value::Null, false) + } + }; let rpc_start = Instant::now(); - let _ = client + let response = client .call( "session.tools.handlePendingToolCall", Some(serde_json::json!({ @@ -2049,14 +2155,33 @@ async fn handle_notification( })), ) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - session_id = %sid, - request_id = %request_id, - tool_call_id = %tool_call_id, - tool_name = %tool_name, - "Session::handle_notification response sent successfully" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + "Session::handle_notification response sent successfully" + ), + Err(e) if handler_succeeded && result_converted => error!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + stage = "SendingResult", + "tool call failed" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + tool_call_id = %tool_call_id, + tool_name = %tool_name, + "failed to deliver tool call response back to the runtime" + ), + } } .instrument(span), ); @@ -2077,6 +2202,11 @@ async fn handle_notification( // handler installed, don't respond — another client on the // same CLI may handle it. let Some(elicitation_handler) = handlers.elicitation.clone() else { + warn!( + session_id = %session_id, + request_id = %request_id, + "received elicitation request without a registered elicitation handler" + ); return; }; let elicitation_data: ElicitationRequestedData = @@ -2143,7 +2273,15 @@ async fn handle_notification( }); let result = match handler_task.await { Ok(r) => r, - Err(_) => cancel.clone(), + Err(e) => { + error!( + error = %e, + session_id = %sid, + request_id = %request_id, + "elicitation handler failed; cancelling pending elicitation" + ); + cancel.clone() + } }; let rpc_start = Instant::now(); if let Err(e) = client @@ -2158,8 +2296,13 @@ async fn handle_notification( .await { // RPC failed — attempt cancel as last resort - warn!(error = %e, "handlePendingElicitation failed, sending cancel"); - let _ = client + warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + "failed to deliver elicitation response back to the runtime; sending cancel" + ); + if let Err(e) = client .call( "session.ui.handlePendingElicitation", Some(serde_json::json!({ @@ -2168,7 +2311,15 @@ async fn handle_notification( "result": cancel, })), ) - .await; + .await + { + warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + "failed to deliver elicitation cancellation back to the runtime" + ); + } } else { tracing::debug!( elapsed_ms = rpc_start.elapsed().as_millis(), @@ -2245,10 +2396,18 @@ async fn handle_notification( }); let result = match handler_task.await { Ok(result) => result, - Err(_) => cancel, + Err(e) => { + warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + "MCP OAuth request failed; cancelling pending request" + ); + cancel + } }; let rpc_start = Instant::now(); - let _ = client + let response = client .call( "session.mcp.oauth.handlePendingRequest", Some(serde_json::json!({ @@ -2258,10 +2417,20 @@ async fn handle_notification( })), ) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - "Session::handle_notification MCP auth response sent" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + "Session::handle_notification MCP auth response sent" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + "failed to deliver MCP OAuth response back to the runtime" + ), + } } .instrument(span), ); @@ -2282,10 +2451,23 @@ async fn handle_notification( tokio::spawn( async move { let request_id = data.request_id; - let ack_error = match command_handlers.get(&data.command_name).cloned() { - None => Some(format!("Unknown command: {}", data.command_name)), + let command_name = data.command_name.clone(); + let ack_error = match command_handlers.get(&command_name).cloned() { + None => { + if tracing::enabled!(tracing::Level::WARN) { + let registered_command_names = + registered_names(command_handlers.as_ref()); + warn!( + session_id = %sid, + request_id = %request_id, + command_name = %command_name, + registered_command_names = %registered_command_names, + "received command request without a registered command handler" + ); + } + Some(format!("Unknown command: {}", data.command_name)) + } Some(handler) => { - let command_name = data.command_name.clone(); let ctx = CommandContext { session_id: sid.clone(), command: data.command, @@ -2303,7 +2485,16 @@ async fn handle_notification( ); match result { Ok(()) => None, - Err(e) => Some(e.to_string()), + Err(e) => { + error!( + error = %e, + session_id = %sid, + request_id = %request_id, + command_name = %command_name, + "command handler failed" + ); + Some(e.to_string()) + } } } }; @@ -2311,19 +2502,36 @@ async fn handle_notification( "sessionId": sid, "requestId": request_id, }); + let has_ack_error = ack_error.is_some(); if let Some(error_msg) = ack_error { params["error"] = serde_json::Value::String(error_msg); } let rpc_start = Instant::now(); - let _ = client + let response = client .call("session.commands.handlePendingCommand", Some(params)) .await; - tracing::debug!( - elapsed_ms = rpc_start.elapsed().as_millis(), - session_id = %sid, - request_id = %request_id, - "Session::handle_notification response sent successfully" - ); + match response { + Ok(_) => tracing::debug!( + elapsed_ms = rpc_start.elapsed().as_millis(), + session_id = %sid, + request_id = %request_id, + "Session::handle_notification response sent successfully" + ), + Err(e) if has_ack_error => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + command_name = %command_name, + "failed to deliver command error back to the runtime" + ), + Err(e) => warn!( + error = %e, + session_id = %sid, + request_id = %request_id, + command_name = %command_name, + "failed to deliver command response back to the runtime" + ), + } } .instrument(span), );