.Net: Improve logging for function calls processor and kernel function

dotnet/SK-dotnet.sln

@@ -349,6 +349,7 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "FunctionCalling", "Function
 	ProjectSection(SolutionItems) = preProject
 		src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallingUtilities.props = src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallingUtilities.props
 		src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallsProcessor.cs = src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallsProcessor.cs
+		src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallsProcessorLoggerExtensions.cs = src\InternalUtilities\connectors\AI\FunctionCalling\FunctionCallsProcessorLoggerExtensions.cs
 	EndProjectSection
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Connectors.Weaviate.UnitTests", "src\Connectors\Connectors.Weaviate.UnitTests\Connectors.Weaviate.UnitTests.csproj", "{E8FC97B0-B417-4A90-993C-B8AA9223B058}"

dotnet/src/Connectors/Connectors.OpenAI/Core/ClientCore.cs

@@ -88,7 +88,7 @@ internal ClientCore(
         HttpClient? httpClient = null,
         ILogger? logger = null)
     {
-        this.FunctionCallsProcessor = new FunctionCallsProcessor(this.Logger);
+        this.FunctionCallsProcessor = new FunctionCallsProcessor(logger);
 
         // Empty constructor will be used when inherited by a specialized Client.
         if (modelId is null

dotnet/src/InternalUtilities/connectors/AI/FunctionCalling/FunctionCallsProcessor.cs

@@ -91,6 +91,8 @@ public FunctionCallsProcessor(ILogger? logger = null)
 
         var configuration = behavior.GetConfiguration(new(chatHistory) { Kernel = kernel, RequestSequenceIndex = requestIndex });
 
+        this._logger.LogFunctionChoiceBehaviorConfiguration(configuration);
+
         // Disable auto invocation if no kernel is provided.
         configuration.AutoInvoke = kernel is not null && configuration.AutoInvoke;
 
@@ -99,24 +101,13 @@ public FunctionCallsProcessor(ILogger? logger = null)
         if (requestIndex >= maximumAutoInvokeAttempts)
         {
             configuration.AutoInvoke = false;
-            if (this._logger!.IsEnabled(LogLevel.Debug))
-            {
-                this._logger.LogDebug("Maximum auto-invoke ({MaximumAutoInvoke}) reached.", maximumAutoInvokeAttempts);
-            }
+            this._logger.LogMaximumNumberOfAutoInvocationsPerUserRequestReached(maximumAutoInvokeAttempts);
         }
         // Disable auto invocation if we've exceeded the allowed limit of in-flight auto-invokes. See XML comment for the "MaxInflightAutoInvokes" const for more details.
         else if (s_inflightAutoInvokes.Value >= MaxInflightAutoInvokes)
         {
             configuration.AutoInvoke = false;
-            if (this._logger!.IsEnabled(LogLevel.Debug))
-            {
-                this._logger.LogDebug("Maximum auto-invoke ({MaxInflightAutoInvoke}) reached.", MaxInflightAutoInvokes);
-            }
-        }
-
-        if (configuration.Functions?.Count == 0)
-        {
-            this._logger.LogDebug("No functions provided to AI model. Function calling is disabled.");
+            this._logger.LogMaximumNumberOfInFlightAutoInvocationsReached(MaxInflightAutoInvokes);
         }
 
         return configuration;
@@ -146,28 +137,14 @@ public FunctionCallsProcessor(ILogger? logger = null)
     {
         var functionCalls = FunctionCallContent.GetFunctionCalls(chatMessageContent).ToList();
 
-        if (this._logger.IsEnabled(LogLevel.Debug))
-        {
-            this._logger.LogDebug("Function calls: {Calls}", functionCalls.Count);
-        }
-        if (this._logger.IsEnabled(LogLevel.Trace))
-        {
-            var messages = new List<string>(functionCalls.Count);
-            foreach (var call in functionCalls)
-            {
-                var argumentsString = call.Arguments is not null ? $"({string.Join(",", call.Arguments.Select(a => $"{a.Key}={a.Value}"))})" : "()";
-                var pluginName = string.IsNullOrEmpty(call.PluginName) ? string.Empty : $"{call.PluginName}-";
-                messages.Add($"{pluginName}{call.FunctionName}{argumentsString}");
-            }
-            this._logger.LogTrace("Function calls: {Calls}", string.Join(", ", messages));
-        }
+        this._logger.LogFunctionCalls(functionCalls);
 
         // Add the result message to the caller's chat history;
         // this is required for AI model to understand the function results.
         chatHistory.Add(chatMessageContent);
 
         var functionTasks = options.AllowConcurrentInvocation && functionCalls.Count > 1 ?
-            new List<Task<(string? Result, string? ErrorMessage, FunctionCallContent FunctionCall, bool Terminate)>>(functionCalls.Count) :
+            new List<Task<(string? Result, string? ErrorMessage, FunctionCallContent FunctionCall, AutoFunctionInvocationContext Context)>>(functionCalls.Count) :
             null;
 
         // We must send back a result for every function call, regardless of whether we successfully executed it or not.
@@ -205,15 +182,16 @@ public FunctionCallsProcessor(ILogger? logger = null)
                 FunctionSequenceIndex = functionCallIndex,
                 FunctionCount = functionCalls.Count,
                 CancellationToken = cancellationToken,
-                IsStreaming = isStreaming
+                IsStreaming = isStreaming,
+                ToolCallId = functionCall.Id
             };
 
-            var functionTask = Task.Run<(string? Result, string? ErrorMessage, FunctionCallContent FunctionCall, bool Terminate)>(async () =>
+            var functionTask = Task.Run<(string? Result, string? ErrorMessage, FunctionCallContent FunctionCall, AutoFunctionInvocationContext Context)>(async () =>
             {
                 s_inflightAutoInvokes.Value++;
                 try
                 {
-                    invocationContext = await OnAutoFunctionInvocationAsync(kernel, invocationContext, async (context) =>
+                    invocationContext = await this.OnAutoFunctionInvocationAsync(kernel, invocationContext, async (context) =>
                     {
                         // Check if filter requested termination.
                         if (context.Terminate)
@@ -231,12 +209,12 @@ public FunctionCallsProcessor(ILogger? logger = null)
                 catch (Exception e)
 #pragma warning restore CA1031 // Do not catch general exception types
                 {
-                    return (null, $"Error: Exception while invoking function. {e.Message}", functionCall, false);
+                    return (null, $"Error: Exception while invoking function. {e.Message}", functionCall, invocationContext);
                 }
 
                 // Apply any changes from the auto function invocation filters context to final result.
                 var stringResult = ProcessFunctionResult(invocationContext.Result.GetValue<object>() ?? string.Empty);
-                return (stringResult, null, functionCall, invocationContext.Terminate);
+                return (stringResult, null, functionCall, invocationContext);
             }, cancellationToken);
 
             // If concurrent invocation is enabled, add the task to the list for later waiting. Otherwise, join with it now.
@@ -250,9 +228,9 @@ public FunctionCallsProcessor(ILogger? logger = null)
                 this.AddFunctionCallResultToChatHistory(chatHistory, functionResult.FunctionCall, functionResult.Result, functionResult.ErrorMessage);
 
                 // If filter requested termination, return last chat history message.
-                if (functionResult.Terminate)
+                if (functionResult.Context.Terminate)
                 {
-                    this._logger.LogDebug("Filter requested termination of automatic function invocation.");
+                    this._logger.LogAutoFunctionInvocationProcessTermination(functionResult.Context);
                     return chatHistory.Last();
                 }
             }
@@ -270,16 +248,16 @@ public FunctionCallsProcessor(ILogger? logger = null)
             {
                 this.AddFunctionCallResultToChatHistory(chatHistory, functionTask.Result.FunctionCall, functionTask.Result.Result, functionTask.Result.ErrorMessage);
 
-                if (functionTask.Result.Terminate)
+                if (functionTask.Result.Context.Terminate)
                 {
+                    this._logger.LogAutoFunctionInvocationProcessTermination(functionTask.Result.Context);
                     terminationRequested = true;
                 }
             }
 
             // If filter requested termination, return last chat history message.
             if (terminationRequested)
             {
-                this._logger.LogDebug("Filter requested termination of automatic function invocation.");
                 return chatHistory.Last();
             }
         }
@@ -297,9 +275,9 @@ public FunctionCallsProcessor(ILogger? logger = null)
     private void AddFunctionCallResultToChatHistory(ChatHistory chatHistory, FunctionCallContent functionCall, string? result, string? errorMessage = null)
     {
         // Log any error
-        if (errorMessage is not null && this._logger.IsEnabled(LogLevel.Debug))
+        if (errorMessage is not null)
         {
-            this._logger.LogDebug("Failed to handle function request ({Id}). {Error}", functionCall.Id, errorMessage);
+            this._logger.LogFunctionCallRequestFailure(functionCall, errorMessage);
         }
 
         result ??= errorMessage ?? string.Empty;
@@ -317,12 +295,12 @@ private void AddFunctionCallResultToChatHistory(ChatHistory chatHistory, Functio
     /// <param name="context">The auto function invocation context.</param>
     /// <param name="functionCallCallback">The function to call after the filters.</param>
     /// <returns>The auto function invocation context.</returns>
-    private static async Task<AutoFunctionInvocationContext> OnAutoFunctionInvocationAsync(
+    private async Task<AutoFunctionInvocationContext> OnAutoFunctionInvocationAsync(
         Kernel kernel,
         AutoFunctionInvocationContext context,
         Func<AutoFunctionInvocationContext, Task> functionCallCallback)
     {
-        await InvokeFilterOrFunctionAsync(kernel.AutoFunctionInvocationFilters, functionCallCallback, context).ConfigureAwait(false);
+        await this.InvokeFilterOrFunctionAsync(kernel.AutoFunctionInvocationFilters, functionCallCallback, context).ConfigureAwait(false);
 
         return context;
     }
@@ -334,16 +312,20 @@ private static async Task<AutoFunctionInvocationContext> OnAutoFunctionInvocatio
     /// Second parameter of filter is callback. It can be either filter on <paramref name="index"/> + 1 position or function if there are no remaining filters to execute.
     /// Function will be always executed as last step after all filters.
     /// </summary>
-    private static async Task InvokeFilterOrFunctionAsync(
+    private async Task InvokeFilterOrFunctionAsync(
         IList<IAutoFunctionInvocationFilter>? autoFunctionInvocationFilters,
         Func<AutoFunctionInvocationContext, Task> functionCallCallback,
         AutoFunctionInvocationContext context,
         int index = 0)
     {
         if (autoFunctionInvocationFilters is { Count: > 0 } && index < autoFunctionInvocationFilters.Count)
         {
-            await autoFunctionInvocationFilters[index].OnAutoFunctionInvocationAsync(context,
-                (context) => InvokeFilterOrFunctionAsync(autoFunctionInvocationFilters, functionCallCallback, context, index + 1)).ConfigureAwait(false);
+            this._logger.LogAutoFunctionInvocationFilterContext(context);
+
+            await autoFunctionInvocationFilters[index].OnAutoFunctionInvocationAsync(
+                context,
+                (context) => this.InvokeFilterOrFunctionAsync(autoFunctionInvocationFilters, functionCallCallback, context, index + 1)
+            ).ConfigureAwait(false);
         }
         else
         {

dotnet/src/InternalUtilities/connectors/AI/FunctionCalling/FunctionCallsProcessorLoggerExtensions.cs

@@ -0,0 +1,147 @@
+// Copyright (c) Microsoft. All rights reserved.
+
+using System;
+using System.Collections.Generic;
+using System.Diagnostics.CodeAnalysis;
+using System.Linq;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.SemanticKernel.Connectors.FunctionCalling;
+
+[ExcludeFromCodeCoverage]
+internal static partial class FunctionCallsProcessorLoggingExtensions
+{
+    /// <summary>
+    /// Action to log the <see cref="FunctionChoiceBehaviorConfiguration"/>.
+    /// </summary>
+    private static readonly Action<ILogger, string, bool, bool, bool?, string, Exception?> s_logFunctionChoiceBehaviorConfiguration =
+        LoggerMessage.Define<string, bool, bool, bool?, string>(
+            logLevel: LogLevel.Debug,
+            eventId: 0,
+            "Function choice behavior configuration: Choice:{Choice}, AutoInvoke:{AutoInvoke}, AllowConcurrentInvocation:{AllowConcurrentInvocation}, AllowParallelCalls:{AllowParallelCalls} Functions:{Functions}");
+
+    /// <summary>
+    /// Action to log function calls.
+    /// </summary>
+    private static readonly Action<ILogger, string, Exception?> s_logFunctionCalls =
+        LoggerMessage.Define<string>(
+            logLevel: LogLevel.Debug,
+            eventId: 0,
+            "Function calls: {Calls}");
+
+    /// <summary>
+    /// Action to log auto function invocation filter context.
+    /// </summary>
+    private static readonly Action<ILogger, string, string?, bool, int, int, int, Exception?> s_logAutoFunctionInvocationFilterContext =
+        LoggerMessage.Define<string, string?, bool, int, int, int>(
+            logLevel: LogLevel.Debug,
+            eventId: 0,
+            "Auto function invocation filter context: Name:{Name}, Id:{Id}, IsStreaming:{IsStreaming} FunctionSequenceIndex:{FunctionSequenceIndex}, RequestSequenceIndex:{RequestSequenceIndex}, FunctionCount:{FunctionCount}");
+
+    /// <summary>
+    /// Action to log auto function invocation filter termination.
+    /// </summary>
+    private static readonly Action<ILogger, string, string?, Exception?> s_logAutoFunctionInvocationFilterTermination =
+        LoggerMessage.Define<string, string?>(
+            logLevel: LogLevel.Debug,
+            eventId: 0,
+            "Auto function invocation filter requested termination: Name:{Name}, Id:{Id}");
+
+    /// <summary>
+    /// Logs <see cref="FunctionChoiceBehaviorConfiguration"/>.
+    /// </summary>
+    public static void LogFunctionChoiceBehaviorConfiguration(this ILogger logger, FunctionChoiceBehaviorConfiguration configuration)
+    {
+        if (logger.IsEnabled(LogLevel.Debug))
+        {
+            var functionsLog = (configuration.Functions != null && configuration.Functions.Any())
+                ? string.Join(", ", configuration.Functions.Select(f => FunctionName.ToFullyQualifiedName(f.Name, f.PluginName)))
+                : "None (Function calling is disabled)";
+
+            s_logFunctionChoiceBehaviorConfiguration(
+                logger,
+                configuration.Choice.Label,
+                configuration.AutoInvoke,
+                configuration.Options.AllowConcurrentInvocation,
+                configuration.Options.AllowParallelCalls,
+                functionsLog,
+                null);
+        }
+    }
+
+    /// <summary>
+    /// Logs function calls.
+    /// </summary>
+    public static void LogFunctionCalls(this ILogger logger, List<FunctionCallContent> functionCalls)
+    {
+        if (logger.IsEnabled(LogLevel.Debug))
+        {
+            s_logFunctionCalls(
+                logger,
+                string.Join(", ", functionCalls.Select(call => $"{FunctionName.ToFullyQualifiedName(call.FunctionName, call.PluginName)} [Id: {call.Id}]")),
+                null
+            );
+        }
+    }
+
+    /// <summary>
+    /// Logs the <see cref="AutoFunctionInvocationContext"/>.
+    /// </summary>
+    public static void LogAutoFunctionInvocationFilterContext(this ILogger logger, AutoFunctionInvocationContext context)
+    {
+        if (logger.IsEnabled(LogLevel.Debug))
+        {
+            var fqn = FunctionName.ToFullyQualifiedName(context.Function.Name, context.Function.PluginName);
+
+            s_logAutoFunctionInvocationFilterContext(
+                    logger,
+                    fqn,
+                    context.ToolCallId,
+                    context.IsStreaming,
+                    context.FunctionSequenceIndex,
+                    context.RequestSequenceIndex,
+                    context.FunctionCount,
+                    null);
+        }
+    }
+
+    /// <summary>
+    /// Logs the auto function invocation process termination.
+    /// </summary>
+    public static void LogAutoFunctionInvocationProcessTermination(this ILogger logger, AutoFunctionInvocationContext context)
+    {
+        if (logger.IsEnabled(LogLevel.Debug))
+        {
+            var fqn = FunctionName.ToFullyQualifiedName(context.Function.Name, context.Function.PluginName);
+
+            s_logAutoFunctionInvocationFilterTermination(logger, fqn, context.ToolCallId, null);
+        }
+    }
+
+    /// <summary>
+    /// Logs function call request failure.
+    /// </summary>
+    public static void LogFunctionCallRequestFailure(this ILogger logger, FunctionCallContent functionCall, string error)
+    {
+        if (logger.IsEnabled(LogLevel.Debug))
+        {
+            var fqn = FunctionName.ToFullyQualifiedName(functionCall.FunctionName, functionCall.PluginName);
+
+            logger.LogDebug("Function call request failed: Name:{Name}, Id:{Id}", fqn, functionCall.Id);
+        }
+
+        // Log error at trace level only because it may contain sensitive information.
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            var fqn = FunctionName.ToFullyQualifiedName(functionCall.FunctionName, functionCall.PluginName);
+
+            logger.LogTrace("Function call request failed: Name:{Name}, Id:{Id}, Error:{Error}", fqn, functionCall.Id, error);
+        }
+    }
+
+    [LoggerMessage(EventId = 0, Level = LogLevel.Debug, Message = "The maximum limit of {MaxNumberOfAutoInvocations} auto invocations per user request has been reached. Auto invocation is now disabled.")]
+    public static partial void LogMaximumNumberOfAutoInvocationsPerUserRequestReached(this ILogger logger, int maxNumberOfAutoInvocations);
+
+    [LoggerMessage(EventId = 0, Level = LogLevel.Debug, Message = "The maximum limit of {MaxNumberOfInflightAutoInvocations} in-flight auto invocations has been reached. Auto invocation is now disabled.")]
+    public static partial void LogMaximumNumberOfInFlightAutoInvocationsReached(this ILogger logger, int maxNumberOfInflightAutoInvocations);
+}