.Net: Log complex objects as Jsons (#4247)

### Motivation and Context

<!-- Thank you for your contribution to the semantic-kernel repo!
Please help reviewers and future users, providing the following
information:
  1. Why is this change required?
  2. What problem does it solve?
  3. What scenario does it contribute to?
  4. If it fixes an open issue, please link to the issue here.
-->
Logging complex objects as Json allows developers to see the entire
object and makes it easier to parse the logs.
Related: #4129

### Description

<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->
Log complex objects as Jsons while keeping the high-performant logging
pattern.

![image](https://github.com/microsoft/semantic-kernel/assets/12570346/2208e308-4240-46dd-abc0-64d21a911a12)

### Contribution Checklist

<!-- Before submitting this PR, please make sure: -->

- [ ] The code builds clean without any errors or warnings
- [ ] The PR follows the [SK Contribution
Guidelines](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md)
and the [pre-submission formatting
script](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md#development-scripts)
raises no violations
- [ ] All unit tests pass, and I have added new tests where possible
- [ ] I didn't break anyone 😄

---------

Co-authored-by: Mark Wallace <127216156+markwallace-microsoft@users.noreply.github.com>

dotnet/src/InternalUtilities/planning/PlannerInstrumentation.cs

@@ -3,6 +3,7 @@
 using System;
 using System.Diagnostics;
 using System.Diagnostics.Metrics;
+using System.Text.Json;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
@@ -109,38 +110,54 @@ internal static partial class PlannerInstrumentation
     }
 
     #region CreatePlan Logging helpers
+#pragma warning disable SYSLIB1006 // Multiple logging methods cannot use the same event id within a class
     [LoggerMessage(
         EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan creation started.")]
     static partial void LogCreatePlanStarted(this ILogger logger);
 
     [LoggerMessage(
-        EventId = 1,
+        EventId = 0,
         Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
         Message = "Goal: {Goal}")]
     static partial void LogGoal(this ILogger logger, string goal);
 
     [LoggerMessage(
-        EventId = 2,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan created.")]
     static partial void LogPlanCreated(this ILogger logger);
 
-    [LoggerMessage(
-        EventId = 3,
-        Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
-        Message = "Plan:\n{Plan}")]
-    static partial void LogPlan(this ILogger logger, object plan);
+    private static readonly Action<ILogger, string, Exception?> s_logPlan =
+        LoggerMessage.Define<string>(
+            logLevel: LogLevel.Trace,   // Sensitive data, logging as trace, disabled by default
+            eventId: 0,
+            "Plan:\n{Plan}");
+    private static void LogPlan(this ILogger logger, object plan)
+    {
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            try
+            {
+                var jsonString = JsonSerializer.Serialize(plan);
+                s_logPlan(logger, jsonString, null);
+            }
+            catch (NotSupportedException ex)
+            {
+                s_logPlan(logger, "Failed to serialize plan to Json", ex);
+            }
+        }
+    }
 
     [LoggerMessage(
-        EventId = 4,
+        EventId = 0,
         Level = LogLevel.Error,
         Message = "Plan creation failed. Error: {Message}")]
     static partial void LogCreatePlanError(this ILogger logger, Exception exception, string message);
 
     [LoggerMessage(
-        EventId = 5,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan creation duration: {Duration}s.")]
     static partial void LogCreatePlanDuration(this ILogger logger, double duration);
@@ -149,34 +166,53 @@ internal static partial class PlannerInstrumentation
 
     #region InvokePlan Logging helpers
     [LoggerMessage(
-        EventId = 6,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan execution started.")]
     static partial void LogInvokePlanStarted(this ILogger logger);
 
     [LoggerMessage(
-        EventId = 7,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan executed successfully.")]
     static partial void LogInvokePlanSuccess(this ILogger logger);
 
-    [LoggerMessage(
-        EventId = 8,
-        Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
-        Message = "Plan result: {PlanResult}")]
-    static partial void LogPlanResult(this ILogger logger, object planResult);
+    private static readonly Action<ILogger, string, Exception?> s_logPlanResult =
+        LoggerMessage.Define<string>(
+            logLevel: LogLevel.Trace,   // Sensitive data, logging as trace, disabled by default
+            eventId: 0,
+            "Plan result: {Result}");
+
+    private static void LogPlanResult(this ILogger logger, object planResult)
+    {
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            try
+            {
+                var jsonString = planResult.GetType() == typeof(string)
+                    ? planResult.ToString()
+                    : JsonSerializer.Serialize(planResult);
+                s_logPlanResult(logger, jsonString, null);
+            }
+            catch (NotSupportedException ex)
+            {
+                s_logPlanResult(logger, "Failed to serialize plan result to Json", ex);
+            }
+        }
+    }
 
     [LoggerMessage(
-        EventId = 9,
+        EventId = 0,
         Level = LogLevel.Error,
         Message = "Plan creation failed. Error: {Message}")]
     static partial void LogInvokePlanError(this ILogger logger, Exception exception, string message);
 
     [LoggerMessage(
-        EventId = 10,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Plan creation duration: {Duration}s.")]
     static partial void LogInvokePlanDuration(this ILogger logger, double duration);
 
+#pragma warning restore SYSLIB1006 // Multiple logging methods cannot use the same event id within a class
     #endregion
 }

dotnet/src/SemanticKernel.Abstractions/Functions/KernelFunction.cs

@@ -121,7 +121,8 @@ internal KernelFunction(string name, string description, IReadOnlyList<KernelPar
 
         // Ensure arguments are initialized.
         arguments ??= new KernelArguments();
-        logger.LogFunctionInvokingWithArguments(this.Name, arguments);
+        logger.LogFunctionInvoking(this.Name);
+        logger.LogFunctionArguments(arguments);
 
         TagList tags = new() { { MeasurementFunctionTagName, this.Name } };
         long startingTimestamp = Stopwatch.GetTimestamp();
@@ -153,7 +154,8 @@ internal KernelFunction(string name, string description, IReadOnlyList<KernelPar
                 throw new OperationCanceledException($"A {nameof(Kernel)}.{nameof(Kernel.FunctionInvoked)} event handler requested cancellation after function invocation.");
             }
 
-            logger.LogFunctionInvokedSuccess(functionResult.Value);
+            logger.LogFunctionInvokedSuccess(this.Name);
+            logger.LogFunctionResultValue(functionResult.Value);
 
             return functionResult;
         }
@@ -232,7 +234,8 @@ internal KernelFunction(string name, string description, IReadOnlyList<KernelPar
         ILogger logger = kernel.LoggerFactory.CreateLogger(this.Name) ?? NullLogger.Instance;
 
         arguments ??= new KernelArguments();
-        logger.LogFunctionStreamingInvokingWithArguments(this.Name, arguments);
+        logger.LogFunctionStreamingInvoking(this.Name);
+        logger.LogFunctionArguments(arguments);
 
         TagList tags = new() { { MeasurementFunctionTagName, this.Name } };
         long startingTimestamp = Stopwatch.GetTimestamp();

dotnet/src/SemanticKernel.Abstractions/Functions/KernelFunctionLogMessages.cs

@@ -1,6 +1,9 @@
 // Copyright (c) Microsoft. All rights reserved.
 
+#pragma warning disable SYSLIB1006 // Multiple logging methods cannot use the same event id within a class
+
 using System;
+using System.Text.Json;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.SemanticKernel;
@@ -17,36 +20,80 @@ internal static partial class KernelFunctionLogMessages
     /// </summary>
     [LoggerMessage(
         EventId = 0,
-        Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
-        Message = "Function {FunctionName} invoking. Arguments: {Arguments}.")]
-    public static partial void LogFunctionInvokingWithArguments(
+        Level = LogLevel.Information,
+        Message = "Function {FunctionName} invoking.")]
+    public static partial void LogFunctionInvoking(
         this ILogger logger,
-        string functionName,
-        KernelArguments arguments);
+        string functionName);
 
     /// <summary>
-    /// Logs cancellation of a <see cref="KernelFunction"/>.
+    /// Logs arguments to a <see cref="KernelFunction"/>.
+    /// The action provides the benefit of caching the template parsing result for better performance.
+    /// And the public method is a helper to serialize the arguments.
     /// </summary>
-    [LoggerMessage(
-        EventId = 1,
-        Level = LogLevel.Information,
-        Message = "Function canceled prior to invocation.")]
-    public static partial void LogFunctionCanceledPriorToInvoking(this ILogger logger);
+    private static readonly Action<ILogger, string, Exception?> s_logFunctionArguments =
+        LoggerMessage.Define<string>(
+            logLevel: LogLevel.Trace,   // Sensitive data, logging as trace, disabled by default
+            eventId: 0,
+            "Function arguments: {Arguments}");
+    public static void LogFunctionArguments(this ILogger logger, KernelArguments arguments)
+    {
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            try
+            {
+                var jsonString = JsonSerializer.Serialize(arguments);
+                s_logFunctionArguments(logger, jsonString, null);
+            }
+            catch (NotSupportedException ex)
+            {
+                s_logFunctionArguments(logger, "Failed to serialize arguments to Json", ex);
+            }
+        }
+    }
 
     /// <summary>
     /// Logs successful invocation of a <see cref="KernelFunction"/>.
     /// </summary>
     [LoggerMessage(
-        EventId = 2,
-        Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
-        Message = "Function succeeded. Result: {Result}")]
-    public static partial void LogFunctionInvokedSuccess(this ILogger logger, object? result);
+        EventId = 0,
+        Level = LogLevel.Information,
+        Message = "Function {FunctionName} succeeded.")]
+    public static partial void LogFunctionInvokedSuccess(this ILogger logger, string functionName);
+
+    /// <summary>
+    /// Logs result of a <see cref="KernelFunction"/>.
+    /// The action provides the benefit of caching the template parsing result for better performance.
+    /// And the public method is a helper to serialize the result.
+    /// </summary>
+    private static readonly Action<ILogger, string, Exception?> s_logFunctionResultValue =
+        LoggerMessage.Define<string>(
+            logLevel: LogLevel.Trace,   // Sensitive data, logging as trace, disabled by default
+            eventId: 0,
+            "Function result: {ResultValue}");
+    public static void LogFunctionResultValue(this ILogger logger, object? resultValue)
+    {
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            try
+            {
+                var jsonString = resultValue?.GetType() == typeof(string)
+                    ? resultValue.ToString()
+                    : JsonSerializer.Serialize(resultValue);
+                s_logFunctionResultValue(logger, jsonString, null);
+            }
+            catch (NotSupportedException ex)
+            {
+                s_logFunctionResultValue(logger, "Failed to serialize result value to Json", ex);
+            }
+        }
+    }
 
     /// <summary>
     /// Logs <see cref="KernelFunction"/> error.
     /// </summary>
     [LoggerMessage(
-        EventId = 3,
+        EventId = 0,
         Level = LogLevel.Error,
         Message = "Function failed. Error: {Message}")]
     public static partial void LogFunctionError(
@@ -58,7 +105,7 @@ internal static partial class KernelFunctionLogMessages
     /// Logs <see cref="KernelFunction"/> complete.
     /// </summary>
     [LoggerMessage(
-        EventId = 4,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Function completed. Duration: {Duration}s")]
     public static partial void LogFunctionComplete(
@@ -69,19 +116,18 @@ internal static partial class KernelFunctionLogMessages
     /// Logs streaming invocation of a <see cref="KernelFunction"/>.
     /// </summary>
     [LoggerMessage(
-        EventId = 5,
-        Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
-        Message = "Function {FunctionName} streaming. Arguments: {Arguments}.")]
-    public static partial void LogFunctionStreamingInvokingWithArguments(
+        EventId = 0,
+        Level = LogLevel.Information,
+        Message = "Function {FunctionName} streaming.")]
+    public static partial void LogFunctionStreamingInvoking(
         this ILogger logger,
-        string functionName,
-        KernelArguments arguments);
+        string functionName);
 
     /// <summary>
     /// Logs <see cref="KernelFunction"/> streaming complete.
     /// </summary>
     [LoggerMessage(
-        EventId = 6,
+        EventId = 0,
         Level = LogLevel.Information,
         Message = "Function streaming completed. Duration: {Duration}s.")]
     public static partial void LogFunctionStreamingComplete(