.Net - Agent Logging (#6075)

### 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.
-->

Introduce logging for _Agent Framework_

### Description
<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->

Basic diagnostics are critical.
Added a single logging sample in _Getting Started_. (Enabling logging
for all samples obscures the sample focus)

Logging Levels:

- Pre-Action ([verb]-ing): DEBUG
- Post-Action ([verb]-ed): INFORMATION (This often contains the result
of the action)
- Exception Thrown: ERROR (intuitive)
- Sensitive Data: TRACE (Tao was explicit on this / I think from working
with Toub)

Intent is that INFORMATION is for the messages we want enabled by
default for a deployed service (with agents). Whereas DEBUG/TRACE
messages are more opt-in detail for developers, as you've suggested.

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

- [X] The code builds clean without any errors or warnings
- [X] 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
- [X] All unit tests pass, and I have added new tests where possible
- [X] I didn't break anyone 😄

dotnet/samples/GettingStartedWithAgents/Step3_Chat.cs

@@ -22,12 +22,14 @@ public class Step3_Chat(ITestOutputHelper output) : BaseTest(output)
         If not, provide insight on how to refine suggested copy without example.
         """;
 
-    private const string CopyWriterName = "Writer";
+    private const string CopyWriterName = "CopyWriter";
     private const string CopyWriterInstructions =
         """
         You are a copywriter with ten years of experience and are known for brevity and a dry humor.
-        You're laser focused on the goal at hand. Don't waste time with chit chat.
         The goal is to refine and decide on the single best copy as an expert in the field.
+        Only provide a single proposal per response.
+        You're laser focused on the goal at hand.
+        Don't waste time with chit chat.
         Consider suggestions when refining an idea.
         """;
 

dotnet/samples/GettingStartedWithAgents/Step6_DependencyInjection.cs

@@ -68,7 +68,7 @@ public async Task RunAsync()
         // Create a service provider for resolving registered services
         await using ServiceProvider serviceProvider = serviceContainer.BuildServiceProvider();
 
-        // If an application follows DI guidelines, the following line is unnecessary because DI will inject an instance of the KernelClient class to a class that references it.
+        // If an application follows DI guidelines, the following line is unnecessary because DI will inject an instance of the AgentClient class to a class that references it.
         // DI container guidelines - https://learn.microsoft.com/en-us/dotnet/core/extensions/dependency-injection-guidelines#recommendations
         AgentClient agentClient = serviceProvider.GetRequiredService<AgentClient>();
 

dotnet/samples/GettingStartedWithAgents/Step7_Logging.cs

@@ -0,0 +1,100 @@
+// Copyright (c) Microsoft. All rights reserved.
+using Microsoft.Extensions.Logging;
+using Microsoft.SemanticKernel;
+using Microsoft.SemanticKernel.Agents;
+using Microsoft.SemanticKernel.Agents.Chat;
+using Microsoft.SemanticKernel.ChatCompletion;
+
+namespace GettingStarted;
+
+/// <summary>
+/// A repeat of <see cref="Step3_Chat"/> with logging enabled via assignment
+/// of a <see cref="LoggerFactory"/> to <see cref="AgentChat.LoggerFactory"/>.
+/// </summary>
+/// <remarks>
+/// Samples become super noisy with logging always enabled.
+/// </remarks>
+public class Step7_Logging(ITestOutputHelper output) : BaseTest(output)
+{
+    private const string ReviewerName = "ArtDirector";
+    private const string ReviewerInstructions =
+        """
+        You are an art director who has opinions about copywriting born of a love for David Ogilvy.
+        The goal is to determine if the given copy is acceptable to print.
+        If so, state that it is approved.
+        If not, provide insight on how to refine suggested copy without examples.
+        """;
+
+    private const string CopyWriterName = "CopyWriter";
+    private const string CopyWriterInstructions =
+        """
+        You are a copywriter with ten years of experience and are known for brevity and a dry humor.
+        The goal is to refine and decide on the single best copy as an expert in the field.
+        Only provide a single proposal per response.
+        You're laser focused on the goal at hand.
+        Don't waste time with chit chat.
+        Consider suggestions when refining an idea.
+        """;
+
+    [Fact]
+    public async Task RunAsync()
+    {
+        // Define the agents
+        ChatCompletionAgent agentReviewer =
+            new()
+            {
+                Instructions = ReviewerInstructions,
+                Name = ReviewerName,
+                Kernel = this.CreateKernelWithChatCompletion(),
+            };
+
+        ChatCompletionAgent agentWriter =
+            new()
+            {
+                Instructions = CopyWriterInstructions,
+                Name = CopyWriterName,
+                Kernel = this.CreateKernelWithChatCompletion(),
+            };
+
+        // Create a chat for agent interaction.
+        AgentGroupChat chat =
+            new(agentWriter, agentReviewer)
+            {
+                // This is all that is required to enable logging across the agent framework/
+                LoggerFactory = this.LoggerFactory,
+                ExecutionSettings =
+                    new()
+                    {
+                        // Here a TerminationStrategy subclass is used that will terminate when
+                        // an assistant message contains the term "approve".
+                        TerminationStrategy =
+                            new ApprovalTerminationStrategy()
+                            {
+                                // Only the art-director may approve.
+                                Agents = [agentReviewer],
+                                // Limit total number of turns
+                                MaximumIterations = 10,
+                            }
+                    }
+            };
+
+        // Invoke chat and display messages.
+        string input = "concept: maps made out of egg cartons.";
+        chat.AddChatMessage(new ChatMessageContent(AuthorRole.User, input));
+        Console.WriteLine($"# {AuthorRole.User}: '{input}'");
+
+        await foreach (var content in chat.InvokeAsync())
+        {
+            Console.WriteLine($"# {content.Role} - {content.AuthorName ?? "*"}: '{content.Content}'");
+        }
+
+        Console.WriteLine($"# IS COMPLETE: {chat.IsComplete}");
+    }
+
+    private sealed class ApprovalTerminationStrategy : TerminationStrategy
+    {
+        // Terminate when the final message contains the term "approve"
+        protected override Task<bool> ShouldAgentTerminateAsync(Agent agent, IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken)
+            => Task.FromResult(history[history.Count - 1].Content?.Contains("approve", StringComparison.OrdinalIgnoreCase) ?? false);
+    }
+}

dotnet/samples/GettingStartedWithAgents/Step7_OpenAIAssistant.cs → dotnet/samples/GettingStartedWithAgents/Step8_OpenAIAssistant.cs

@@ -12,7 +12,7 @@ namespace GettingStarted;
 /// <see cref="OpenAIAssistantAgent"/> is no different from <see cref="ChatCompletionAgent"/>
 /// even with with a <see cref="KernelPlugin"/>.
 /// </summary>
-public class Step7_OpenAIAssistant(ITestOutputHelper output) : BaseTest(output)
+public class Step8_OpenAIAssistant(ITestOutputHelper output) : BaseTest(output)
 {
     private const string HostName = "Host";
     private const string HostInstructions = "Answer questions about the menu.";

dotnet/src/Agents/Abstractions/Agent.cs

@@ -3,6 +3,7 @@
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.SemanticKernel.Agents;
 
@@ -52,11 +53,12 @@ public abstract class Agent
     /// <summary>
     /// Produce the an <see cref="AgentChannel"/> appropriate for the agent type.
     /// </summary>
+    /// <param name="logger">An agent specific logger.</param>
     /// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
     /// <returns>An <see cref="AgentChannel"/> appropriate for the agent type.</returns>
     /// <remarks>
     /// Every agent conversation, or <see cref="AgentChat"/>, will establish one or more <see cref="AgentChannel"/>
     /// objects according to the specific <see cref="Agent"/> type.
     /// </remarks>
-    protected internal abstract Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken);
+    protected internal abstract Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken);
 }

dotnet/src/Agents/Abstractions/AgentChannel.cs

@@ -2,15 +2,22 @@
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Microsoft.SemanticKernel.Agents;
 
 /// <summary>
 /// Defines the communication protocol for a particular <see cref="Agent"/> type.
-/// An agent provides it own <see cref="AgentChannel"/> via <see cref="Agent.CreateChannelAsync(CancellationToken)"/>.
+/// An agent provides it own <see cref="AgentChannel"/> via <see cref="Agent.CreateChannelAsync"/>.
 /// </summary>
 public abstract class AgentChannel
 {
+    /// <summary>
+    /// The <see cref="ILogger"/> associated with the <see cref="AgentChannel"/>.
+    /// </summary>
+    public ILogger Logger { get; set; } = NullLogger.Instance;
+
     /// <summary>
     /// Receive the conversation messages.  Used when joining a conversation and also during each agent interaction..
     /// </summary>
@@ -38,7 +45,7 @@ public abstract class AgentChannel
 
 /// <summary>
 /// Defines the communication protocol for a particular <see cref="Agent"/> type.
-/// An agent provides it own <see cref="AgentChannel"/> via <see cref="Agent.CreateChannelAsync(CancellationToken)"/>.
+/// An agent provides it own <see cref="AgentChannel"/> via <see cref="Agent.CreateChannelAsync"/>.
 /// </summary>
 /// <typeparam name="TAgent">The agent type for this channel</typeparam>
 /// <remarks>

dotnet/src/Agents/Abstractions/AgentChat.cs

@@ -4,6 +4,8 @@
 using System.Runtime.CompilerServices;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.SemanticKernel.Agents.Extensions;
 using Microsoft.SemanticKernel.Agents.Internal;
 using Microsoft.SemanticKernel.ChatCompletion;
@@ -24,13 +26,24 @@ public abstract class AgentChat
     private readonly Dictionary<Agent, string> _channelMap; // Map agent to its channel-hash: one entry per agent.
 
     private int _isActive;
+    private ILogger? _logger;
 
     /// <summary>
     /// Indicates if a chat operation is active.  Activity is defined as
     /// any the execution of any public method.
     /// </summary>
     public bool IsActive => Interlocked.CompareExchange(ref this._isActive, 1, 1) > 0;
 
+    /// <summary>
+    /// The <see cref="ILoggerFactory"/> associated with the <see cref="AgentChat"/>.
+    /// </summary>
+    public ILoggerFactory LoggerFactory { get; init; } = NullLoggerFactory.Instance;
+
+    /// <summary>
+    /// The <see cref="ILogger"/> associated with this chat.
+    /// </summary>
+    protected ILogger Logger => this._logger ??= this.LoggerFactory.CreateLogger(this.GetType());
+
     /// <summary>
     /// Exposes the internal history to subclasses.
     /// </summary>
@@ -68,6 +81,8 @@ public abstract class AgentChat
     {
         this.SetActivityOrThrow(); // Disallow concurrent access to chat history
 
+        this.Logger.LogDebug("[{MethodName}] Source: {MessageSourceType}/{MessageSourceId}", nameof(GetChatMessagesAsync), agent?.GetType().Name ?? "primary", agent?.Id ?? "primary");
+
         try
         {
             IAsyncEnumerable<ChatMessageContent>? messages = null;
@@ -148,6 +163,11 @@ public void AddChatMessages(IReadOnlyList<ChatMessageContent> messages)
             }
         }
 
+        if (this.Logger.IsEnabled(LogLevel.Debug)) // Avoid boxing if not enabled
+        {
+            this.Logger.LogDebug("[{MethodName}] Adding Messages: {MessageCount}", nameof(AddChatMessages), messages.Count);
+        }
+
         try
         {
             // Append to chat history
@@ -157,6 +177,11 @@ public void AddChatMessages(IReadOnlyList<ChatMessageContent> messages)
             // Note: Able to queue messages without synchronizing channels.
             var channelRefs = this._agentChannels.Select(kvp => new ChannelReference(kvp.Value, kvp.Key));
             this._broadcastQueue.Enqueue(channelRefs, messages);
+
+            if (this.Logger.IsEnabled(LogLevel.Information)) // Avoid boxing if not enabled
+            {
+                this.Logger.LogInformation("[{MethodName}] Added Messages: {MessageCount}", nameof(AddChatMessages), messages.Count);
+            }
         }
         finally
         {
@@ -180,6 +205,8 @@ public void AddChatMessages(IReadOnlyList<ChatMessageContent> messages)
     {
         this.SetActivityOrThrow(); // Disallow concurrent access to chat history
 
+        this.Logger.LogDebug("[{MethodName}] Invoking agent {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
+
         try
         {
             // Get or create the required channel and block until channel is synchronized.
@@ -190,13 +217,15 @@ public void AddChatMessages(IReadOnlyList<ChatMessageContent> messages)
             List<ChatMessageContent> messages = [];
             await foreach (ChatMessageContent message in channel.InvokeAsync(agent, cancellationToken).ConfigureAwait(false))
             {
+                this.Logger.LogTrace("[{MethodName}] Agent message {AgentType}: {Message}", nameof(InvokeAgentAsync), agent.GetType(), message);
+
                 // Add to primary history
                 this.History.Add(message);
                 messages.Add(message);
 
+                // Don't expose internal messages to caller.
                 if (message.Role == AuthorRole.Tool || message.Items.All(i => i is FunctionCallContent))
                 {
-                    // Don't expose internal messages to caller.
                     continue;
                 }
 
@@ -211,6 +240,8 @@ await foreach (ChatMessageContent message in channel.InvokeAsync(agent, cancella
                     .Where(kvp => kvp.Value != channel)
                     .Select(kvp => new ChannelReference(kvp.Value, kvp.Key));
             this._broadcastQueue.Enqueue(channelRefs, messages);
+
+            this.Logger.LogInformation("[{MethodName}] Invoked agent {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
         }
         finally
         {
@@ -223,13 +254,21 @@ async Task<AgentChannel> GetOrCreateChannelAsync()
             AgentChannel channel = await this.SynchronizeChannelAsync(channelKey, cancellationToken).ConfigureAwait(false);
             if (channel == null)
             {
-                channel = await agent.CreateChannelAsync(cancellationToken).ConfigureAwait(false);
+                this.Logger.LogDebug("[{MethodName}] Creating channel for {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
+
+                // Creating an agent-typed logger for CreateChannelAsync
+                channel = await agent.CreateChannelAsync(this.LoggerFactory.CreateLogger(agent.GetType()), cancellationToken).ConfigureAwait(false);
+                // Creating an channel-typed logger for the channel
+                channel.Logger = this.LoggerFactory.CreateLogger(channel.GetType());
+
                 this._agentChannels.Add(channelKey, channel);
 
                 if (this.History.Count > 0)
                 {
                     await channel.ReceiveAsync(this.History, cancellationToken).ConfigureAwait(false);
                 }
+
+                this.Logger.LogInformation("[{MethodName}] Created channel for {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
             }
 
             return channel;

dotnet/src/Agents/Abstractions/AggregatorAgent.cs

@@ -3,6 +3,7 @@
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.SemanticKernel.Agents;
 
@@ -43,8 +44,15 @@ protected internal override IEnumerable<string> GetChannelKeys()
     }
 
     /// <inheritdoc/>
-    protected internal override Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
+    protected internal override Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken)
     {
-        return Task.FromResult<AgentChannel>(new AggregatorChannel(chatProvider.Invoke()));
+        logger.LogDebug("[{MethodName}] Creating channel {ChannelType}", nameof(CreateChannelAsync), nameof(AggregatorChannel));
+
+        AgentChat chat = chatProvider.Invoke();
+        AggregatorChannel channel = new(chat);
+
+        logger.LogInformation("[{MethodName}] Created channel {ChannelType} ({ChannelMode}) with: {AgentChatType}", nameof(CreateChannelAsync), nameof(AggregatorChannel), this.Mode, chat.GetType());
+
+        return Task.FromResult<AgentChannel>(channel);
     }
 }

dotnet/src/Agents/Abstractions/ChatHistoryChannel.cs

@@ -25,7 +25,7 @@ public class ChatHistoryChannel : AgentChannel
             throw new KernelException($"Invalid channel binding for agent: {agent.Id} ({agent.GetType().FullName})");
         }
 
-        await foreach (var message in historyHandler.InvokeAsync(this._history, cancellationToken).ConfigureAwait(false))
+        await foreach (var message in historyHandler.InvokeAsync(this._history, this.Logger, cancellationToken).ConfigureAwait(false))
         {
             this._history.Add(message);
 

dotnet/src/Agents/Abstractions/ChatHistoryKernelAgent.cs

@@ -2,6 +2,7 @@
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.SemanticKernel.Agents;
 
@@ -17,13 +18,14 @@ protected internal sealed override IEnumerable<string> GetChannelKeys()
     }
 
     /// <inheritdoc/>
-    protected internal sealed override Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
+    protected internal sealed override Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken)
     {
         return Task.FromResult<AgentChannel>(new ChatHistoryChannel());
     }
 
     /// <inheritdoc/>
     public abstract IAsyncEnumerable<ChatMessageContent> InvokeAsync(
         IReadOnlyList<ChatMessageContent> history,
+        ILogger logger,
         CancellationToken cancellationToken = default);
 }

dotnet/src/Agents/Abstractions/IChatHistoryHandler.cs

@@ -1,6 +1,7 @@
 // Copyright (c) Microsoft. All rights reserved.
 using System.Collections.Generic;
 using System.Threading;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.SemanticKernel.Agents;
 
@@ -13,9 +14,11 @@ public interface IChatHistoryHandler
     /// Entry point for calling into an agent from a a <see cref="ChatHistoryChannel"/>.
     /// </summary>
     /// <param name="history">The chat history at the point the channel is created.</param>
+    /// <param name="logger">The logger associated with the <see cref="ChatHistoryChannel"/></param>
     /// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
     /// <returns>Asynchronous enumeration of messages.</returns>
     IAsyncEnumerable<ChatMessageContent> InvokeAsync(
         IReadOnlyList<ChatMessageContent> history,
+        ILogger logger,
         CancellationToken cancellationToken = default);
 }