Skip to content

Commit

Permalink
.Net Agents - Add dynamic logging methods (#7069)
Browse files Browse the repository at this point in the history
### 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.
-->

Migrate logging to dynamic logging methods for better maintability and
discoverability (best practice).

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

Moved each instance of logging a message into a class specific
log-message file.

### 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 😄
  • Loading branch information
crickman committed Jul 11, 2024
1 parent 6944914 commit 6b59077
Show file tree
Hide file tree
Showing 24 changed files with 855 additions and 90 deletions.
22 changes: 8 additions & 14 deletions dotnet/src/Agents/Abstractions/AgentChat.cs
Original file line number Diff line number Diff line change
Expand Up @@ -81,7 +81,7 @@ public async IAsyncEnumerable<ChatMessageContent> GetChatMessagesAsync(
{
this.SetActivityOrThrow(); // Disallow concurrent access to chat history

this.Logger.LogDebug("[{MethodName}] Source: {MessageSourceType}/{MessageSourceId}", nameof(GetChatMessagesAsync), agent?.GetType().Name ?? "primary", agent?.Id ?? "primary");
this.Logger.LogAgentChatGetChatMessages(nameof(GetChatMessagesAsync), agent);

try
{
Expand Down Expand Up @@ -163,10 +163,7 @@ 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);
}
this.Logger.LogAgentChatAddingMessages(nameof(AddChatMessages), messages.Count);

try
{
Expand All @@ -178,10 +175,7 @@ public void AddChatMessages(IReadOnlyList<ChatMessageContent> messages)
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);
}
this.Logger.LogAgentChatAddedMessages(nameof(AddChatMessages), messages.Count);
}
finally
{
Expand All @@ -205,7 +199,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(
{
this.SetActivityOrThrow(); // Disallow concurrent access to chat history

this.Logger.LogDebug("[{MethodName}] Invoking agent {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokingAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);

try
{
Expand All @@ -217,7 +211,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(
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);
this.Logger.LogAgentChatInvokedAgentMessage(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, message);

// Add to primary history
this.History.Add(message);
Expand All @@ -241,7 +235,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(
.Select(kvp => new ChannelReference(kvp.Value, kvp.Key));
this._broadcastQueue.Enqueue(channelRefs, messages.Where(m => m.Role != AuthorRole.Tool).ToArray());

this.Logger.LogInformation("[{MethodName}] Invoked agent {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokedAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
}
finally
{
Expand All @@ -254,7 +248,7 @@ async Task<AgentChannel> GetOrCreateChannelAsync()
AgentChannel? channel = await this.SynchronizeChannelAsync(channelKey, cancellationToken).ConfigureAwait(false);
if (channel is null)
{
this.Logger.LogDebug("[{MethodName}] Creating channel for {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatCreatingChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);

channel = await agent.CreateChannelAsync(cancellationToken).ConfigureAwait(false);

Expand All @@ -265,7 +259,7 @@ async Task<AgentChannel> GetOrCreateChannelAsync()
await channel.ReceiveAsync(this.History, cancellationToken).ConfigureAwait(false);
}

this.Logger.LogInformation("[{MethodName}] Created channel for {AgentType}: {AgentId}", nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatCreatedChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
}

return channel;
Expand Down
5 changes: 2 additions & 3 deletions dotnet/src/Agents/Abstractions/AggregatorAgent.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace Microsoft.SemanticKernel.Agents;

Expand Down Expand Up @@ -46,12 +45,12 @@ protected internal override IEnumerable<string> GetChannelKeys()
/// <inheritdoc/>
protected internal override Task<AgentChannel> CreateChannelAsync(CancellationToken cancellationToken)
{
this.Logger.LogDebug("[{MethodName}] Creating channel {ChannelType}", nameof(CreateChannelAsync), nameof(AggregatorChannel));
this.Logger.LogAggregatorAgentCreatingChannel(nameof(CreateChannelAsync), nameof(AggregatorChannel));

AgentChat chat = chatProvider.Invoke();
AggregatorChannel channel = new(chat);

this.Logger.LogInformation("[{MethodName}] Created channel {ChannelType} ({ChannelMode}) with: {AgentChatType}", nameof(CreateChannelAsync), nameof(AggregatorChannel), this.Mode, chat.GetType());
this.Logger.LogAggregatorAgentCreatedChannel(nameof(CreateChannelAsync), nameof(AggregatorChannel), this.Mode, chat.GetType());

return Task.FromResult<AgentChannel>(channel);
}
Expand Down
135 changes: 135 additions & 0 deletions dotnet/src/Agents/Abstractions/Logging/AgentChatLogMessages.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,135 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using System.Diagnostics.CodeAnalysis;
using Microsoft.Extensions.Logging;

namespace Microsoft.SemanticKernel.Agents;

#pragma warning disable SYSLIB1006 // Multiple logging methods cannot use the same event id within a class

/// <summary>
/// Extensions for logging <see cref="AggregatorAgent"/> invocations.
/// </summary>
/// <remarks>
/// This extension uses the <see cref="LoggerMessageAttribute"/> to
/// generate logging code at compile time to achieve optimized code.
/// </remarks>
[ExcludeFromCodeCoverage]
internal static partial class AgentChatLogMessages
{
/// <summary>
/// Logs retrieval of <see cref="AgentChat"/> messages.
/// </summary>
private static readonly Action<ILogger, string, string, string, Exception?> s_logAgentChatGetChatMessages =
LoggerMessage.Define<string, string, string>(
logLevel: LogLevel.Debug,
eventId: 0,
"[{MethodName}] Source: {MessageSourceType}/{MessageSourceId}.");
public static void LogAgentChatGetChatMessages(
this ILogger logger,
string methodName,
Agent? agent)
{
if (logger.IsEnabled(LogLevel.Debug))
{
if (null == agent)
{
s_logAgentChatGetChatMessages(logger, methodName, "primary", "primary", null);
}
else
{
s_logAgentChatGetChatMessages(logger, methodName, agent.GetType().Name, agent.Id, null);
}
}
}

/// <summary>
/// Logs <see cref="AgentChat"/> adding messages (started).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "[{MethodName}] Adding Messages: {MessageCount}.")]
public static partial void LogAgentChatAddingMessages(
this ILogger logger,
string methodName,
int messageCount);

/// <summary>
/// Logs <see cref="AgentChat"/> added messages (complete).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Adding Messages: {MessageCount}.")]
public static partial void LogAgentChatAddedMessages(
this ILogger logger,
string methodName,
int messageCount);

/// <summary>
/// Logs <see cref="AgentChat"/> invoking agent (started).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "[{MethodName}] Invoking agent {AgentType}/{AgentId}.")]
public static partial void LogAgentChatInvokingAgent(
this ILogger logger,
string methodName,
Type agentType,
string agentId);

/// <summary>
/// Logs <see cref="AgentChat"/> invoked agent message
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Trace,
Message = "[{MethodName}] Agent message {AgentType}/{AgentId}: {Message}.")]
public static partial void LogAgentChatInvokedAgentMessage(
this ILogger logger,
string methodName,
Type agentType,
string agentId,
ChatMessageContent message);

/// <summary>
/// Logs <see cref="AgentChat"/> invoked agent (complete).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Invoked agent {AgentType}/{AgentId}.")]
public static partial void LogAgentChatInvokedAgent(
this ILogger logger,
string methodName,
Type agentType,
string agentId);

/// <summary>
/// Logs <see cref="AgentChat"/> creating agent channel (started).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "[{MethodName}] Creating channel for {AgentType}: {AgentId}")]
public static partial void LogAgentChatCreatingChannel(
this ILogger logger,
string methodName,
Type agentType,
string agentId);

/// <summary>
/// Logs <see cref="AgentChat"/> created agent channel (complete).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Created channel for {AgentType}: {AgentId}")]
public static partial void LogAgentChatCreatedChannel(
this ILogger logger,
string methodName,
Type agentType,
string agentId);
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,45 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using System.Diagnostics.CodeAnalysis;
using Microsoft.Extensions.Logging;

namespace Microsoft.SemanticKernel.Agents;

#pragma warning disable SYSLIB1006 // Multiple logging methods cannot use the same event id within a class

/// <summary>
/// Extensions for logging <see cref="AggregatorAgent"/> invocations.
/// </summary>
/// <remarks>
/// This extension uses the <see cref="LoggerMessageAttribute"/> to
/// generate logging code at compile time to achieve optimized code.
/// </remarks>
[ExcludeFromCodeCoverage]
internal static partial class AggregatorAgentLogMessages
{
/// <summary>
/// Logs <see cref="AggregatorAgent"/> creating channel (started).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "[{MethodName}] Creating channel {ChannelType}.")]
public static partial void LogAggregatorAgentCreatingChannel(
this ILogger logger,
string methodName,
string channelType);

/// <summary>
/// Logs <see cref="AggregatorAgent"/> created channel (complete).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Created channel {ChannelType} ({ChannelMode}) with: {AgentChatType}.")]
public static partial void LogAggregatorAgentCreatedChannel(
this ILogger logger,
string methodName,
string channelType,
AggregatorMode channelMode,
Type agentChatType);
}
14 changes: 7 additions & 7 deletions dotnet/src/Agents/Core/AgentGroupChat.cs
Original file line number Diff line number Diff line change
Expand Up @@ -72,12 +72,12 @@ public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync([Enumerat
this.IsComplete = false;
}

this.Logger.LogDebug("[{MethodName}] Invoking chat: {Agents}", nameof(InvokeAsync), string.Join(", ", this.Agents.Select(a => $"{a.GetType()}:{a.Id}")));
this.Logger.LogAgentGroupChatInvokingAgents(nameof(InvokeAsync), this.Agents);

for (int index = 0; index < this.ExecutionSettings.TerminationStrategy.MaximumIterations; index++)
{
// Identify next agent using strategy
this.Logger.LogDebug("[{MethodName}] Selecting agent: {StrategyType}", nameof(InvokeAsync), this.ExecutionSettings.SelectionStrategy.GetType());
this.Logger.LogAgentGroupChatSelectingAgent(nameof(InvokeAsync), this.ExecutionSettings.SelectionStrategy.GetType());

Agent agent;
try
Expand All @@ -86,11 +86,11 @@ public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync([Enumerat
}
catch (Exception exception)
{
this.Logger.LogError(exception, "[{MethodName}] Unable to determine next agent.", nameof(InvokeAsync));
this.Logger.LogAgentGroupChatNoAgentSelected(nameof(InvokeAsync), exception);
throw;
}

this.Logger.LogInformation("[{MethodName}] Agent selected {AgentType}: {AgentId} by {StrategyType}", nameof(InvokeAsync), agent.GetType(), agent.Id, this.ExecutionSettings.SelectionStrategy.GetType());
this.Logger.LogAgentGroupChatSelectedAgent(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))
Expand All @@ -110,7 +110,7 @@ public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync([Enumerat
}
}

this.Logger.LogDebug("[{MethodName}] Yield chat - IsComplete: {IsComplete}", nameof(InvokeAsync), this.IsComplete);
this.Logger.LogAgentGroupChatYield(nameof(InvokeAsync), this.IsComplete);
}

/// <summary>
Expand Down Expand Up @@ -143,7 +143,7 @@ public async IAsyncEnumerable<ChatMessageContent> InvokeAsync(
{
this.EnsureStrategyLoggerAssignment();

this.Logger.LogDebug("[{MethodName}] Invoking chat: {AgentType}: {AgentId}", nameof(InvokeAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentGroupChatInvokingAgent(nameof(InvokeAsync), agent.GetType(), agent.Id);

if (isJoining)
{
Expand All @@ -161,7 +161,7 @@ public async IAsyncEnumerable<ChatMessageContent> InvokeAsync(
yield return message;
}

this.Logger.LogDebug("[{MethodName}] Yield chat - IsComplete: {IsComplete}", nameof(InvokeAsync), this.IsComplete);
this.Logger.LogAgentGroupChatYield(nameof(InvokeAsync), this.IsComplete);
}

/// <summary>
Expand Down
6 changes: 1 addition & 5 deletions dotnet/src/Agents/Core/Chat/AggregatorTerminationStrategy.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace Microsoft.SemanticKernel.Agents.Chat;

Expand Down Expand Up @@ -39,10 +38,7 @@ 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);
}
this.Logger.LogAggregatorTerminationStrategyEvaluating(nameof(ShouldAgentTerminateAsync), this._strategies.Length, this.Condition);

var strategyExecution = this._strategies.Select(s => s.ShouldTerminateAsync(agent, history, cancellationToken));

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,6 @@
using System.Text.Json;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace Microsoft.SemanticKernel.Agents.Chat;

Expand Down Expand Up @@ -70,11 +69,11 @@ public sealed override async Task<Agent> NextAsync(IReadOnlyList<Agent> agents,
{ 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);
this.Logger.LogKernelFunctionSelectionStrategyInvokingFunction(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);
this.Logger.LogKernelFunctionSelectionStrategyInvokedFunction(nameof(NextAsync), this.Function.PluginName, this.Function.Name, result.ValueType);

string? agentName = this.ResultParser.Invoke(result);
if (string.IsNullOrEmpty(agentName))
Expand Down
Loading

0 comments on commit 6b59077

Please sign in to comment.