diff --git a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs index 156e89c7bdf..fdc7d57b1ea 100644 --- a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs +++ b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs @@ -17,6 +17,7 @@ #pragma warning disable CA2213 // Disposable fields should be disposed #pragma warning disable S2219 // Runtime type checking should be simplified #pragma warning disable S3353 // Unchanged local variables should be "const" +#pragma warning disable SA1204 // Static members should appear before non-static members namespace Microsoft.Extensions.AI; @@ -934,6 +935,15 @@ private bool ShouldTerminateLoopBasedOnHandleableFunctions(List added, ref in consecutiveErrorCount++; if (consecutiveErrorCount > MaximumConsecutiveErrorsPerRequest) { + LogMaxConsecutiveErrorsExceeded(MaximumConsecutiveErrorsPerRequest); + var allExceptionsArray = added .SelectMany(m => m.Contents.OfType()) .Select(frc => frc.Exception!) @@ -1115,6 +1129,15 @@ private async Task ProcessFunctionCallAsync( AIFunctionDeclaration? tool = FindTool(callContent.Name, options?.Tools, AdditionalTools); if (tool is not AIFunction aiFunction) { + if (tool is null) + { + LogFunctionNotFound(callContent.Name); + } + else + { + LogNonInvocableFunction(callContent.Name); + } + return new(terminate: false, FunctionInvocationStatus.NotFound, callContent, result: null, exception: null); } @@ -1151,6 +1174,11 @@ private async Task ProcessFunctionCallAsync( exception: e); } + if (context.Terminate) + { + LogFunctionRequestedTermination(callContent.Name); + } + return new( terminate: context.Terminate, FunctionInvocationStatus.RanToCompletion, @@ -1345,10 +1373,10 @@ private static bool CurrentActivityIsInvokeAgent /// /// 1. Remove all and from the . /// 2. Recreate for any that haven't been executed yet. - /// 3. Genreate failed for any rejected . + /// 3. Generate failed for any rejected . /// 4. add all the new content items to and return them as the pre-invocation history. /// - private static (List? preDownstreamCallHistory, List? approvals) ProcessFunctionApprovalResponses( + private (List? preDownstreamCallHistory, List? approvals) ProcessFunctionApprovalResponses( List originalMessages, bool hasConversationId, string? toolMessageId, string? functionCallContentFallbackMessageId) { // Extract any approval responses where we need to execute or reject the function calls. @@ -1399,7 +1427,7 @@ private static (List? preDownstreamCallHistory, List - private static (List? approvals, List? rejections) ExtractAndRemoveApprovalRequestsAndResponses( + private (List? approvals, List? rejections) ExtractAndRemoveApprovalRequestsAndResponses( List messages) { Dictionary? allApprovalRequestsMessages = null; @@ -1498,6 +1526,8 @@ private static (List? approvals, List? targetList = ref approvalResponse.Approved ? ref approvedFunctionCalls : ref rejectedFunctionCalls; @@ -1516,10 +1546,12 @@ private static (List? approvals, List /// Any rejected approval responses. /// The for the rejected function calls. - private static List? GenerateRejectedFunctionResults(List? rejections) => + private List? GenerateRejectedFunctionResults(List? rejections) => rejections is { Count: > 0 } ? rejections.ConvertAll(m => { + LogFunctionRejected(m.Response.FunctionCall.Name, m.Response.Reason); + string result = "Tool call invocation rejected."; if (!string.IsNullOrWhiteSpace(m.Response.Reason)) { @@ -1679,7 +1711,7 @@ private static bool TryReplaceFunctionCallsWithApprovalRequests(IList /// Replaces all from with /// if any one of them requires approval. /// - private static IList ReplaceFunctionCallsWithApprovalRequests( + private IList ReplaceFunctionCallsWithApprovalRequests( IList messages, params ReadOnlySpan?> toolLists) { @@ -1721,6 +1753,7 @@ private static IList ReplaceFunctionCallsWithApprovalRequests( message.Contents = [.. message.Contents]; var functionCall = (FunctionCallContent)message.Contents[contentIndex]; + LogFunctionRequiresApproval(functionCall.Name); message.Contents[contentIndex] = new FunctionApprovalRequestContent(functionCall.CallId, functionCall); outputMessages[messageIndex] = message; @@ -1785,6 +1818,27 @@ private static TimeSpan GetElapsedTime(long startingTimestamp) => [LoggerMessage(LogLevel.Debug, "Reached maximum iteration count of {MaximumIterationsPerRequest}. Stopping function invocation loop.")] private partial void LogMaximumIterationsReached(int maximumIterationsPerRequest); + [LoggerMessage(LogLevel.Debug, "Function '{FunctionName}' requires approval. Converting to approval request.")] + private partial void LogFunctionRequiresApproval(string functionName); + + [LoggerMessage(LogLevel.Debug, "Processing approval response for '{FunctionName}'. Approved: {Approved}")] + private partial void LogProcessingApprovalResponse(string functionName, bool approved); + + [LoggerMessage(LogLevel.Debug, "Function '{FunctionName}' was rejected. Reason: {Reason}")] + private partial void LogFunctionRejected(string functionName, string? reason); + + [LoggerMessage(LogLevel.Warning, "Maximum consecutive errors ({MaxErrors}) exceeded. Throwing aggregated exceptions.")] + private partial void LogMaxConsecutiveErrorsExceeded(int maxErrors); + + [LoggerMessage(LogLevel.Warning, "Function '{FunctionName}' not found.")] + private partial void LogFunctionNotFound(string functionName); + + [LoggerMessage(LogLevel.Debug, "Function '{FunctionName}' is not invocable (declaration only). Terminating loop.")] + private partial void LogNonInvocableFunction(string functionName); + + [LoggerMessage(LogLevel.Debug, "Function '{FunctionName}' requested termination of the processing loop.")] + private partial void LogFunctionRequestedTermination(string functionName); + /// Provides information about the invocation of a function call. public sealed class FunctionInvocationResult { diff --git a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs index 82264dae76f..e9672275871 100644 --- a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs +++ b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs @@ -2692,4 +2692,215 @@ public async Task RespectsChatOptionsToolsModificationsByFunctionTool_ReplaceWit Assert.Equal(2, callCount); } + + [Fact] + public async Task LogsFunctionNotFound() + { + var collector = new FakeLogCollector(); + ServiceCollection c = new(); + c.AddLogging(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var options = new ChatOptions + { + Tools = [AIFunctionFactory.Create(() => "Result 1", "Func1")] + }; + + List plan = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, [new FunctionCallContent("callId1", "UnknownFunc")]), + new ChatMessage(ChatRole.Tool, [new FunctionResultContent("callId1", result: "Error: Requested function \"UnknownFunc\" not found.")]), + new ChatMessage(ChatRole.Assistant, "world"), + ]; + + Func configure = b => + b.Use((c, services) => new FunctionInvokingChatClient(c, services.GetRequiredService())); + + await InvokeAndAssertAsync(options, plan, null, configure, c.BuildServiceProvider()); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Function 'UnknownFunc' not found") && e.Level == LogLevel.Warning); + } + + [Fact] + public async Task LogsNonInvocableFunction() + { + var collector = new FakeLogCollector(); + ServiceCollection c = new(); + c.AddLogging(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var declarationOnly = AIFunctionFactory.Create(() => "Result 1", "Func1").AsDeclarationOnly(); + var options = new ChatOptions + { + Tools = [declarationOnly] + }; + + List plan = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, [new FunctionCallContent("callId1", "Func1")]), + new ChatMessage(ChatRole.Tool, [new FunctionResultContent("callId1", result: "Should not be produced")]), + new ChatMessage(ChatRole.Assistant, "world"), + ]; + + List expected = plan.Take(2).ToList(); + + Func configure = b => + b.Use((c, services) => new FunctionInvokingChatClient(c, services.GetRequiredService())); + + await InvokeAndAssertAsync(options, plan, expected, configure, c.BuildServiceProvider()); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Function 'Func1' is not invocable (declaration only)") && e.Level == LogLevel.Debug); + } + + [Fact] + public async Task LogsFunctionRequestedTermination() + { + var collector = new FakeLogCollector(); + ServiceCollection c = new(); + c.AddLogging(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var options = new ChatOptions + { + Tools = [AIFunctionFactory.Create(() => + { + var context = FunctionInvokingChatClient.CurrentContext!; + context.Terminate = true; + return "Terminated"; + }, "TerminatingFunc")] + }; + + List plan = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, [new FunctionCallContent("callId1", "TerminatingFunc")]), + new ChatMessage(ChatRole.Tool, [new FunctionResultContent("callId1", result: "Terminated")]), + ]; + + Func configure = b => + b.Use((c, services) => new FunctionInvokingChatClient(c, services.GetRequiredService())); + + await InvokeAndAssertAsync(options, plan, null, configure, c.BuildServiceProvider()); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Function 'TerminatingFunc' requested termination of the processing loop") && e.Level == LogLevel.Debug); + } + + [Fact] + public async Task LogsFunctionRequiresApproval() + { + var collector = new FakeLogCollector(); + ServiceCollection c = new(); + c.AddLogging(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var approvalFunc = new ApprovalRequiredAIFunction(AIFunctionFactory.Create(() => "Result 1", "Func1")); + var options = new ChatOptions + { + Tools = [approvalFunc] + }; + + List plan = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, [new FunctionCallContent("callId1", "Func1")]), + ]; + + // Expected output includes the user message and the approval request + List expected = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, + [ + new FunctionApprovalRequestContent("callId1", new FunctionCallContent("callId1", "Func1")) + ]) + ]; + + Func configure = b => + b.Use((c, services) => new FunctionInvokingChatClient(c, services.GetRequiredService())); + + await InvokeAndAssertAsync(options, plan, expected, configure, c.BuildServiceProvider()); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Function 'Func1' requires approval") && e.Level == LogLevel.Debug); + } + + [Fact] + public async Task LogsProcessingApprovalResponse() + { + var collector = new FakeLogCollector(); + using var loggerFactory = LoggerFactory.Create(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var approvalFunc = new ApprovalRequiredAIFunction(AIFunctionFactory.Create(() => "Result 1", "Func1")); + + using var innerClient = new TestChatClient + { + GetResponseAsyncCallback = (messages, opts, ct) => + Task.FromResult(new ChatResponse(new ChatMessage(ChatRole.Assistant, "world"))) + }; + + using var client = new FunctionInvokingChatClient(innerClient, loggerFactory); + + var options = new ChatOptions { Tools = [approvalFunc] }; + + var messages = new List + { + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, + [ + new FunctionApprovalRequestContent("callId1", new FunctionCallContent("callId1", "Func1")) + ]), + new ChatMessage(ChatRole.User, + [ + new FunctionApprovalResponseContent("callId1", true, new FunctionCallContent("callId1", "Func1")) + ]) + }; + + await client.GetResponseAsync(messages, options); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Processing approval response for 'Func1'. Approved: True") && e.Level == LogLevel.Debug); + } + + [Fact] + public async Task LogsFunctionRejected() + { + var collector = new FakeLogCollector(); + using var loggerFactory = LoggerFactory.Create(b => b.AddProvider(new FakeLoggerProvider(collector)).SetMinimumLevel(LogLevel.Debug)); + + var approvalFunc = new ApprovalRequiredAIFunction(AIFunctionFactory.Create(() => "Result 1", "Func1")); + + using var innerClient = new TestChatClient + { + GetResponseAsyncCallback = (messages, opts, ct) => + Task.FromResult(new ChatResponse(new ChatMessage(ChatRole.Assistant, "world"))) + }; + + using var client = new FunctionInvokingChatClient(innerClient, loggerFactory); + + var options = new ChatOptions { Tools = [approvalFunc] }; + + var messages = new List + { + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, + [ + new FunctionApprovalRequestContent("callId1", new FunctionCallContent("callId1", "Func1")) + ]), + new ChatMessage(ChatRole.User, + [ + new FunctionApprovalResponseContent("callId1", false, new FunctionCallContent("callId1", "Func1")) { Reason = "User denied" } + ]) + }; + + await client.GetResponseAsync(messages, options); + + var logs = collector.GetSnapshot(); + Assert.Contains(logs, e => e.Message.Contains("Function 'Func1' was rejected. Reason: User denied") && e.Level == LogLevel.Debug); + } + + // Note: LogMaxConsecutiveErrorsExceeded is exercised by the existing + // ContinuesWithFailingCallsUntilMaximumConsecutiveErrors test which triggers + // the threshold condition. The logging call is at line 1078 and will execute + // when MaximumConsecutiveErrorsPerRequest is exceeded. }