.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 😄
This commit is contained in:
Chris
2024-05-02 03:08:13 +00:00
committed by GitHub
parent ac6e03ba98
commit 1bcb9ce265
29 changed files with 360 additions and 43 deletions
@@ -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.
""";
@@ -68,7 +68,7 @@ public class Step6_DependencyInjection(ITestOutputHelper output) : BaseTest(outp
// 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>();
@@ -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);
}
}
@@ -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.";
+3 -1
View File
@@ -3,6 +3,7 @@ using System;
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);
}
@@ -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>
+41 -2
View File
@@ -4,6 +4,8 @@ using System.Linq;
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,6 +26,7 @@ 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
@@ -31,6 +34,16 @@ public abstract class AgentChat
/// </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 abstract class AgentChat
}
}
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 abstract class AgentChat
// 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 abstract class AgentChat
{
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 abstract class AgentChat
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 @@ public abstract class AgentChat
.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 @@ public abstract class AgentChat
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;
@@ -3,6 +3,7 @@ using System;
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents;
@@ -43,8 +44,15 @@ public sealed class AggregatorAgent(Func<AgentChat> chatProvider) : Agent
}
/// <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);
}
}
@@ -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);
@@ -2,6 +2,7 @@
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents;
@@ -17,7 +18,7 @@ public abstract class ChatHistoryKernelAgent : KernelAgent, IChatHistoryHandler
}
/// <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());
}
@@ -25,5 +26,6 @@ public abstract class ChatHistoryKernelAgent : KernelAgent, IChatHistoryHandler
/// <inheritdoc/>
public abstract IAsyncEnumerable<ChatMessageContent> InvokeAsync(
IReadOnlyList<ChatMessageContent> history,
ILogger logger,
CancellationToken cancellationToken = default);
}
@@ -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);
}
@@ -93,7 +93,7 @@ internal sealed class BroadcastQueue
{
Exception failure = queueRef.ReceiveFailure;
queueRef.ReceiveFailure = null;
throw new KernelException($"Unexpected failure broadcasting to channel: {channelRef.Channel.GetType().Name}", failure);
throw new KernelException($"Unexpected failure broadcasting to channel: {channelRef.Channel.GetType()}", failure);
}
// Activate non-empty queue
+43 -1
View File
@@ -1,9 +1,12 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using System.Collections.Generic;
using System.Linq;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.SemanticKernel.Agents.Chat;
using Microsoft.SemanticKernel.ChatCompletion;
@@ -56,6 +59,8 @@ public sealed class AgentGroupChat : AgentChat
/// <returns>Asynchronous enumeration of messages.</returns>
public async override IAsyncEnumerable<ChatMessageContent> InvokeAsync([EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this.EnsureStrategyLoggerAssignment();
if (this.IsComplete)
{
// Throw exception if chat is completed and automatic-reset is not enabled.
@@ -67,10 +72,25 @@ public sealed class AgentGroupChat : AgentChat
this.IsComplete = false;
}
this.Logger.LogDebug("[{MethodName}] Invoking chat: {Agents}", nameof(InvokeAsync), string.Join(", ", this.Agents.Select(a => $"{a.GetType()}:{a.Id}")));
for (int index = 0; index < this.ExecutionSettings.TerminationStrategy.MaximumIterations; index++)
{
// Identify next agent using strategy
Agent agent = await this.ExecutionSettings.SelectionStrategy.NextAsync(this.Agents, this.History, cancellationToken).ConfigureAwait(false);
this.Logger.LogDebug("[{MethodName}] Selecting agent: {StrategyType}", nameof(InvokeAsync), this.ExecutionSettings.SelectionStrategy.GetType());
Agent agent;
try
{
agent = await this.ExecutionSettings.SelectionStrategy.NextAsync(this.Agents, this.History, cancellationToken).ConfigureAwait(false);
}
catch (Exception exception)
{
this.Logger.LogError(exception, "[{MethodName}] Unable to determine next agent.", nameof(InvokeAsync));
throw;
}
this.Logger.LogInformation("[{MethodName}] Agent selected {AgentType}: {AgentId} by {StrategyType}", nameof(InvokeAsync), agent.GetType(), agent.Id, this.ExecutionSettings.SelectionStrategy.GetType());
// Invoke agent and process messages along with termination
await foreach (var message in base.InvokeAgentAsync(agent, cancellationToken).ConfigureAwait(false))
@@ -89,6 +109,8 @@ public sealed class AgentGroupChat : AgentChat
break;
}
}
this.Logger.LogDebug("[{MethodName}] Yield chat - IsComplete: {IsComplete}", nameof(InvokeAsync), this.IsComplete);
}
/// <summary>
@@ -119,6 +141,10 @@ public sealed class AgentGroupChat : AgentChat
bool isJoining,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this.EnsureStrategyLoggerAssignment();
this.Logger.LogDebug("[{MethodName}] Invoking chat: {AgentType}: {AgentId}", nameof(InvokeAsync), agent.GetType(), agent.Id);
if (isJoining)
{
this.AddAgent(agent);
@@ -134,6 +160,8 @@ public sealed class AgentGroupChat : AgentChat
yield return message;
}
this.Logger.LogDebug("[{MethodName}] Yield chat - IsComplete: {IsComplete}", nameof(InvokeAsync), this.IsComplete);
}
/// <summary>
@@ -145,4 +173,18 @@ public sealed class AgentGroupChat : AgentChat
this._agents = new(agents);
this._agentIds = new(this._agents.Select(a => a.Id));
}
private void EnsureStrategyLoggerAssignment()
{
// Only invoke logger factory when required.
if (this.ExecutionSettings.SelectionStrategy.Logger == NullLogger.Instance)
{
this.ExecutionSettings.SelectionStrategy.Logger = this.LoggerFactory.CreateLogger(this.ExecutionSettings.SelectionStrategy.GetType());
}
if (this.ExecutionSettings.TerminationStrategy.Logger == NullLogger.Instance)
{
this.ExecutionSettings.TerminationStrategy.Logger = this.LoggerFactory.CreateLogger(this.ExecutionSettings.TerminationStrategy.GetType());
}
}
}
@@ -3,6 +3,7 @@ using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -38,6 +39,11 @@ public sealed class AggregatorTerminationStrategy(params TerminationStrategy[] s
/// <inheritdoc/>
protected override async Task<bool> ShouldAgentTerminateAsync(Agent agent, IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken = default)
{
if (this.Logger.IsEnabled(LogLevel.Debug)) // Avoid boxing if not enabled
{
this.Logger.LogDebug("[{MethodName}] Evaluating termination for {Count} strategies: {Mode}", nameof(ShouldAgentTerminateAsync), this._strategies.Length, this.Condition);
}
var strategyExecution = this._strategies.Select(s => s.ShouldTerminateAsync(agent, history, cancellationToken));
var results = await Task.WhenAll(strategyExecution).ConfigureAwait(false);
@@ -5,6 +5,7 @@ using System.Linq;
using System.Text.Json;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -69,8 +70,12 @@ public class KernelFunctionSelectionStrategy(KernelFunction function, Kernel ker
{ this.HistoryVariableName, JsonSerializer.Serialize(history) }, // TODO: GitHub Task #5894
};
this.Logger.LogDebug("[{MethodName}] Invoking function: {PluginName}.{FunctionName}.", nameof(NextAsync), this.Function.PluginName, this.Function.Name);
FunctionResult result = await this.Function.InvokeAsync(this.Kernel, arguments, cancellationToken).ConfigureAwait(false);
this.Logger.LogInformation("[{MethodName}] Invoked function: {PluginName}.{FunctionName}: {ResultType}", nameof(NextAsync), this.Function.PluginName, this.Function.Name, result.ValueType);
string? agentName = this.ResultParser.Invoke(result);
if (string.IsNullOrEmpty(agentName))
{
@@ -5,6 +5,7 @@ using System.Linq;
using System.Text.Json;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -69,8 +70,12 @@ public class KernelFunctionTerminationStrategy(KernelFunction function, Kernel k
{ this.HistoryVariableName, JsonSerializer.Serialize(history) }, // TODO: GitHub Task #5894
};
this.Logger.LogDebug("[{MethodName}] Invoking function: {PluginName}.{FunctionName}.", nameof(ShouldAgentTerminateAsync), this.Function.PluginName, this.Function.Name);
FunctionResult result = await this.Function.InvokeAsync(this.Kernel, arguments, cancellationToken).ConfigureAwait(false);
this.Logger.LogInformation("[{MethodName}] Invoked function: {PluginName}.{FunctionName}: {ResultType}", nameof(ShouldAgentTerminateAsync), this.Function.PluginName, this.Function.Name, result.ValueType);
return this.ResultParser.Invoke(result);
}
}
@@ -4,6 +4,7 @@ using System.Linq;
using System.Text.RegularExpressions;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -52,15 +53,26 @@ public sealed class RegexTerminationStrategy : TerminationStrategy
// Most recent message
var message = history[history.Count - 1].Content;
if (this.Logger.IsEnabled(LogLevel.Debug)) // Avoid boxing if not enabled
{
this.Logger.LogDebug("[{MethodName}] Evaluating expressions: {ExpressionCount}", nameof(ShouldAgentTerminateAsync), this._expressions.Length);
}
// Evaluate expressions for match
foreach (var expression in this._expressions)
{
this.Logger.LogDebug("[{MethodName}] Evaluating expression: {Expression}", nameof(ShouldAgentTerminateAsync), expression);
if (expression.IsMatch(message))
{
this.Logger.LogInformation("[{MethodName}] Expression matched: {Expression}", nameof(ShouldAgentTerminateAsync), expression);
return Task.FromResult(true);
}
}
this.Logger.LogInformation("[{MethodName}] No expression matched.", nameof(ShouldAgentTerminateAsync));
return Task.FromResult(false);
}
}
@@ -2,6 +2,8 @@
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -10,6 +12,11 @@ namespace Microsoft.SemanticKernel.Agents.Chat;
/// </summary>
public abstract class SelectionStrategy
{
/// <summary>
/// The <see cref="ILogger"/> associated with the <see cref="SelectionStrategy"/>.
/// </summary>
protected internal ILogger Logger { get; internal set; } = NullLogger.Instance;
/// <summary>
/// Determine which agent goes next.
/// </summary>
@@ -2,6 +2,7 @@
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -33,10 +34,20 @@ public sealed class SequentialSelectionStrategy : SelectionStrategy
this._index = 0;
}
if (this.Logger.IsEnabled(LogLevel.Debug)) // Avoid boxing if not enabled
{
this.Logger.LogDebug("[{MethodName}] Prior agent index: {AgentIndex} / {AgentCount}.", nameof(NextAsync), this._index, agents.Count);
}
var agent = agents[this._index];
this._index = (this._index + 1) % agents.Count;
if (this.Logger.IsEnabled(LogLevel.Information)) // Avoid boxing if not enabled
{
this.Logger.LogInformation("[{MethodName}] Current agent index: {AgentIndex} / {AgentCount}", nameof(NextAsync), this._index, agents.Count);
}
return Task.FromResult(agent);
}
}
@@ -3,6 +3,8 @@ using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
namespace Microsoft.SemanticKernel.Agents.Chat;
@@ -34,6 +36,11 @@ public abstract class TerminationStrategy
/// </summary>
public IReadOnlyList<Agent>? Agents { get; set; }
/// <summary>
/// The <see cref="ILogger"/> associated with the <see cref="TerminationStrategy"/>.
/// </summary>
protected internal ILogger Logger { get; internal set; } = NullLogger.Instance;
/// <summary>
/// Called to evaluate termination once <see cref="TerminationStrategy.Agents"/> is evaluated.
/// </summary>
@@ -46,14 +53,22 @@ public abstract class TerminationStrategy
/// <param name="history">The most recent message</param>
/// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
/// <returns>True to terminate chat loop.</returns>
public Task<bool> ShouldTerminateAsync(Agent agent, IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken = default)
public async Task<bool> ShouldTerminateAsync(Agent agent, IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken = default)
{
this.Logger.LogDebug("[{MethodName}] Evaluating termination for agent {AgentType}: {AgentId}.", nameof(ShouldTerminateAsync), agent.GetType(), agent.Id);
// `Agents` must contain `agent`, if `Agents` not empty.
if ((this.Agents?.Count ?? 0) > 0 && !this.Agents!.Any(a => a.Id == agent.Id))
{
return Task.FromResult(false);
this.Logger.LogInformation("[{MethodName}] {AgentType} agent out of scope for termination: {AgentId}.", nameof(ShouldTerminateAsync), agent.GetType(), agent.Id);
return false;
}
return this.ShouldAgentTerminateAsync(agent, history, cancellationToken);
bool shouldTerminate = await this.ShouldAgentTerminateAsync(agent, history, cancellationToken).ConfigureAwait(false);
this.Logger.LogInformation("[{MethodName}] Evaluated termination for agent {AgentType}: {AgentId} - {Termination}", nameof(ShouldTerminateAsync), agent.GetType(), agent.Id, shouldTerminate);
return shouldTerminate;
}
}
@@ -2,6 +2,7 @@
using System.Collections.Generic;
using System.Runtime.CompilerServices;
using System.Threading;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel.ChatCompletion;
namespace Microsoft.SemanticKernel.Agents;
@@ -23,6 +24,7 @@ public sealed class ChatCompletionAgent : ChatHistoryKernelAgent
/// <inheritdoc/>
public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync(
IReadOnlyList<ChatMessageContent> history,
ILogger logger,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
var chatCompletionService = this.Kernel.GetRequiredService<IChatCompletionService>();
@@ -36,6 +38,8 @@ public sealed class ChatCompletionAgent : ChatHistoryKernelAgent
int messageCount = chat.Count;
logger.LogDebug("[{MethodName}] Invoking {ServiceType}.", nameof(InvokeAsync), chatCompletionService.GetType());
IReadOnlyList<ChatMessageContent> messages =
await chatCompletionService.GetChatMessageContentsAsync(
chat,
@@ -43,6 +47,11 @@ public sealed class ChatCompletionAgent : ChatHistoryKernelAgent
this.Kernel,
cancellationToken).ConfigureAwait(false);
if (logger.IsEnabled(LogLevel.Information)) // Avoid boxing if not enabled
{
logger.LogInformation("[{MethodName}] Invoked {ServiceType} with message count: {MessageCount}.", nameof(InvokeAsync), chatCompletionService.GetType(), messages.Count);
}
// Capture mutated messages related function calling / tools
for (int messageIndex = messageCount; messageIndex < chat.Count; messageIndex++)
{
@@ -9,6 +9,7 @@ using Azure;
using Azure.AI.OpenAI.Assistants;
using Azure.Core;
using Azure.Core.Pipeline;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel.Agents.OpenAI.Azure;
using Microsoft.SemanticKernel.Http;
@@ -203,10 +204,14 @@ public sealed partial class OpenAIAssistantAgent : KernelAgent
}
/// <inheritdoc/>
protected override async Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
protected override async Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken)
{
logger.LogDebug("[{MethodName}] Creating assistant thread", nameof(CreateChannelAsync));
AssistantThread thread = await this._client.CreateThreadAsync(cancellationToken).ConfigureAwait(false);
logger.LogInformation("[{MethodName}] Created assistant thread: {ThreadId}", nameof(CreateChannelAsync), thread.Id);
return new OpenAIAssistantChannel(this._client, thread.Id, this._config.Polling);
}
@@ -8,6 +8,7 @@ using System.Threading;
using System.Threading.Tasks;
using Azure;
using Azure.AI.OpenAI.Assistants;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel.ChatCompletion;
namespace Microsoft.SemanticKernel.Agents.OpenAI;
@@ -42,7 +43,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
/// <inheritdoc/>
protected override async Task ReceiveAsync(IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken)
{
foreach (var message in history)
foreach (ChatMessageContent message in history)
{
if (string.IsNullOrWhiteSpace(message.Content))
{
@@ -67,7 +68,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
throw new KernelException($"Agent Failure - {nameof(OpenAIAssistantAgent)} agent is deleted: {agent.Id}.");
}
if (!this._agentTools.TryGetValue(agent.Id, out var tools))
if (!this._agentTools.TryGetValue(agent.Id, out ToolDefinition[]? tools))
{
tools = [.. agent.Tools, .. agent.Kernel.Plugins.SelectMany(p => p.Select(f => f.ToToolDefinition(p.Name, FunctionDelimiter)))];
this._agentTools.Add(agent.Id, tools);
@@ -78,6 +79,8 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
this._agentNames.Add(agent.Id, agent.Name);
}
this.Logger.LogDebug("[{MethodName}] Creating run for agent/thrad: {AgentId}/{ThreadId}", nameof(InvokeAsync), agent.Id, this._threadId);
CreateRunOptions options =
new(agent.Id)
{
@@ -88,13 +91,15 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
// Create run
ThreadRun run = await this._client.CreateRunAsync(this._threadId, options, cancellationToken).ConfigureAwait(false);
this.Logger.LogInformation("[{MethodName}] Created run: {RunId}", nameof(InvokeAsync), run.Id);
// Evaluate status and process steps and messages, as encountered.
var processedMessageIds = new HashSet<string>();
HashSet<string> processedMessageIds = [];
do
{
// Poll run and steps until actionable
var steps = await PollRunStatusAsync().ConfigureAwait(false);
PageableList<RunStep> steps = await PollRunStatusAsync().ConfigureAwait(false);
// Is in terminal state?
if (s_terminalStatuses.Contains(run.Status))
@@ -105,26 +110,38 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
// Is tool action required?
if (run.Status == RunStatus.RequiresAction)
{
this.Logger.LogDebug("[{MethodName}] Processing run steps: {RunId}", nameof(InvokeAsync), run.Id);
// Execute functions in parallel and post results at once.
var tasks = steps.Data.SelectMany(step => ExecuteStep(agent, step, cancellationToken)).ToArray();
if (tasks.Length > 0)
{
var results = await Task.WhenAll(tasks).ConfigureAwait(false);
ToolOutput[]? results = await Task.WhenAll(tasks).ConfigureAwait(false);
await this._client.SubmitToolOutputsToRunAsync(run, results, cancellationToken).ConfigureAwait(false);
}
if (this.Logger.IsEnabled(LogLevel.Information)) // Avoid boxing if not enabled
{
this.Logger.LogInformation("[{MethodName}] Processed #{MessageCount} run steps: {RunId}", nameof(InvokeAsync), tasks.Length, run.Id);
}
}
// Enumerate completed messages
var messageDetails =
this.Logger.LogDebug("[{MethodName}] Processing run messages: {RunId}", nameof(InvokeAsync), run.Id);
IEnumerable<RunStepMessageCreationDetails> messageDetails =
steps
.OrderBy(s => s.CompletedAt)
.Select(s => s.StepDetails)
.OfType<RunStepMessageCreationDetails>()
.Where(d => !processedMessageIds.Contains(d.MessageCreation.MessageId));
int messageCount = 0;
foreach (RunStepMessageCreationDetails detail in messageDetails)
{
++messageCount;
// Retrieve the message
ThreadMessage? message = await this.RetrieveMessageAsync(detail, cancellationToken).ConfigureAwait(false);
@@ -156,12 +173,21 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
processedMessageIds.Add(detail.MessageCreation.MessageId);
}
if (this.Logger.IsEnabled(LogLevel.Information)) // Avoid boxing if not enabled
{
this.Logger.LogInformation("[{MethodName}] Processed #{MessageCount} run messages: {RunId}", nameof(InvokeAsync), messageCount, run.Id);
}
}
while (RunStatus.Completed != run.Status);
this.Logger.LogInformation("[{MethodName}] Completed run: {RunId}", nameof(InvokeAsync), run.Id);
// Local function to assist in run polling (participates in method closure).
async Task<PageableList<RunStep>> PollRunStatusAsync()
{
this.Logger.LogInformation("[{MethodName}] Polling run status: {RunId}", nameof(PollRunStatusAsync), run.Id);
int count = 0;
do
@@ -183,6 +209,8 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
}
while (s_pollingStatuses.Contains(run.Status));
this.Logger.LogInformation("[{MethodName}] Run status is {RunStatus}: {RunId}", nameof(PollRunStatusAsync), run.Status, run.Id);
return await this._client.GetRunStepsAsync(run, cancellationToken: cancellationToken).ConfigureAwait(false);
}
}
@@ -196,9 +224,9 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
do
{
messages = await this._client.GetMessagesAsync(this._threadId, limit: 100, ListSortOrder.Descending, after: lastId, null, cancellationToken).ConfigureAwait(false);
foreach (var message in messages)
foreach (ThreadMessage message in messages)
{
var role = new AuthorRole(message.Role.ToString());
AuthorRole role = new(message.Role.ToString());
string? assistantName = null;
if (!string.IsNullOrWhiteSpace(message.AssistantId) &&
@@ -213,7 +241,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
assistantName ??= message.AssistantId;
foreach (var item in message.ContentItems)
foreach (MessageContent item in message.ContentItems)
{
ChatMessageContent? content = null;
@@ -278,7 +306,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
{
ChatMessageContent? messageContent = null;
var textContent = contentMessage.Text.Trim();
string textContent = contentMessage.Text.Trim();
if (!string.IsNullOrWhiteSpace(textContent))
{
@@ -302,7 +330,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
// Process all of the steps that require action
if (step.Status == RunStepStatus.InProgress && step.StepDetails is RunStepToolCallDetails callDetails)
{
foreach (var toolCall in callDetails.ToolCalls.OfType<RunStepFunctionToolCall>())
foreach (RunStepFunctionToolCall toolCall in callDetails.ToolCalls.OfType<RunStepFunctionToolCall>())
{
// Run function
yield return ProcessFunctionStepAsync(toolCall.Id, toolCall);
@@ -312,7 +340,7 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
// Local function for processing the run-step (participates in method closure).
async Task<ToolOutput> ProcessFunctionStepAsync(string callId, RunStepFunctionToolCall functionDetails)
{
var result = await InvokeFunctionCallAsync().ConfigureAwait(false);
object result = await InvokeFunctionCallAsync().ConfigureAwait(false);
if (result is not string toolResult)
{
toolResult = JsonSerializer.Serialize(result);
@@ -322,19 +350,19 @@ internal sealed class OpenAIAssistantChannel(AssistantsClient client, string thr
async Task<object> InvokeFunctionCallAsync()
{
var function = agent.Kernel.GetKernelFunction(functionDetails.Name, FunctionDelimiter);
KernelFunction function = agent.Kernel.GetKernelFunction(functionDetails.Name, FunctionDelimiter);
var functionArguments = new KernelArguments();
KernelArguments functionArguments = new();
if (!string.IsNullOrWhiteSpace(functionDetails.Arguments))
{
var arguments = JsonSerializer.Deserialize<Dictionary<string, object>>(functionDetails.Arguments)!;
foreach (var argument in arguments)
Dictionary<string, object> arguments = JsonSerializer.Deserialize<Dictionary<string, object>>(functionDetails.Arguments)!;
foreach (var argumentKvp in arguments)
{
functionArguments[argument.Key] = argument.Value.ToString();
functionArguments[argumentKvp.Key] = argumentKvp.Value.ToString();
}
}
var result = await function.InvokeAsync(agent.Kernel, functionArguments, cancellationToken).ConfigureAwait(false);
FunctionResult result = await function.InvokeAsync(agent.Kernel, functionArguments, cancellationToken).ConfigureAwait(false);
return result.GetValue<object>() ?? string.Empty;
}
@@ -5,6 +5,7 @@ using System.Linq;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Xunit;
@@ -67,7 +68,7 @@ public class AgentChannelTests
private class TestAgent : KernelAgent
{
protected internal override Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
protected internal override Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken)
{
throw new NotImplementedException();
}
@@ -4,6 +4,7 @@ using System.Linq;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Microsoft.SemanticKernel.ChatCompletion;
@@ -135,7 +136,10 @@ public class AgentChatTests
{
public int InvokeCount { get; private set; }
public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync(IReadOnlyList<ChatMessageContent> history, [EnumeratorCancellation] CancellationToken cancellationToken = default)
public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync(
IReadOnlyList<ChatMessageContent> history,
ILogger logger,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
await Task.Delay(0, cancellationToken);
@@ -3,6 +3,7 @@ using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Microsoft.SemanticKernel.ChatCompletion;
@@ -87,7 +88,7 @@ public class AggregatorAgentTests
Mock<ChatHistoryKernelAgent> agent = new();
ChatMessageContent[] messages = [new ChatMessageContent(AuthorRole.Assistant, "test agent")];
agent.Setup(a => a.InvokeAsync(It.IsAny<IReadOnlyList<ChatMessageContent>>(), It.IsAny<CancellationToken>())).Returns(() => messages.ToAsyncEnumerable());
agent.Setup(a => a.InvokeAsync(It.IsAny<IReadOnlyList<ChatMessageContent>>(), It.IsAny<ILogger>(), It.IsAny<CancellationToken>())).Returns(() => messages.ToAsyncEnumerable());
return agent;
}
@@ -4,6 +4,7 @@ using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Xunit;
@@ -29,7 +30,7 @@ public class ChatHistoryChannelTests
private sealed class TestAgent : KernelAgent
{
protected internal override Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
protected internal override Task<AgentChannel> CreateChannelAsync(ILogger logger, CancellationToken cancellationToken)
{
throw new NotImplementedException();
}
@@ -4,6 +4,7 @@ using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Microsoft.SemanticKernel.Agents.Chat;
@@ -198,7 +199,7 @@ public class AgentGroupChatTests
Mock<ChatHistoryKernelAgent> agent = new();
ChatMessageContent[] messages = [new ChatMessageContent(AuthorRole.Assistant, "test")];
agent.Setup(a => a.InvokeAsync(It.IsAny<IReadOnlyList<ChatMessageContent>>(), It.IsAny<CancellationToken>())).Returns(() => messages.ToAsyncEnumerable());
agent.Setup(a => a.InvokeAsync(It.IsAny<IReadOnlyList<ChatMessageContent>>(), It.IsAny<ILogger>(), It.IsAny<CancellationToken>())).Returns(() => messages.ToAsyncEnumerable());
return agent;
}
@@ -3,6 +3,7 @@ using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Agents;
using Microsoft.SemanticKernel.ChatCompletion;
@@ -59,7 +60,7 @@ public class ChatCompletionAgentTests
ExecutionSettings = new(),
};
var result = await agent.InvokeAsync([]).ToArrayAsync();
var result = await agent.InvokeAsync([], NullLogger.Instance).ToArrayAsync();
Assert.Single(result);