diff --git a/dotnet/src/Session.cs b/dotnet/src/Session.cs index 7d076d14b..3fde91225 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); } } @@ -858,6 +875,10 @@ private async Task TryCancelMcpAuthRequestAsync(string requestId) /// 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 = "PreparingArguments"; try { var invocation = new ToolInvocation @@ -905,6 +926,9 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } var toolTimestamp = Stopwatch.GetTimestamp(); + // 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}", @@ -914,9 +938,11 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, toolCallId, toolName); + stage = "ConvertingResult"; var toolResultObject = ToolResultObject.ConvertFromInvocationResult(result, tool.JsonSerializerOptions); var responseRpcTimestamp = Stopwatch.GetTimestamp(); + 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}", @@ -928,17 +954,23 @@ private async Task ExecuteToolAndRespondAsync(string requestId, string toolName, } catch (Exception ex) { + // 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); } - 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 +1014,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 +1269,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 +1318,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 +1326,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 +1367,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 +1377,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 +2022,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. Stage={Stage}, SessionId={SessionId}, RequestId={RequestId}, ToolCallId={ToolCallId}, Tool={ToolName}")] + private partial void LogToolCallFailed(Exception exception, string sessionId, string requestId, string toolCallId, string toolName, string stage); + + [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 or response delivery 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 or response delivery 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 ea615fbc4..41055273d 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,16 @@ 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, + // 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); } [Fact] diff --git a/dotnet/test/Harness/E2ETestBase.cs b/dotnet/test/Harness/E2ETestBase.cs index 3eb0f0e97..be965ed80 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 0080cbc60..b10da125a 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 diff --git a/go/client.go b/go/client.go index 4e44696a5..610fd624b 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 f00837379..68e2f2363 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 5d45d19ef..721ed9958 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 f3a35967d..6c773ba3d 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 65ff00921..d6688222a 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 3ffda2fa7..6e0d68f71 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 78afdde13..9a79388ff 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 ad0bcb41b..b7e62e539 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 dd2d0a72f..1d262aadd 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 b9d217305..1f293fca8 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), );