Skip to content

Commit

Permalink
.Net: Updated agent logs to include agent name (#10330)
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.
-->

Related: #10174

This PR updates logging messages in Agent Framework to include agent
name. `UnnamedAgent` is used as a default value when the agent's name is
not specified to provide meaningful context in logs.

### 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
@dmytrostruk
dmytrostruk authored Jan 29, 2025
1 parent d015742 commit c311183
Show file tree
Hide file tree
Showing 13 changed files with 93 additions and 56 deletions.
16 changes: 8 additions & 8 deletions dotnet/src/Agents/Abstractions/AgentChat.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -213,7 +213,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(
{
this.SetActivityOrThrow(); // Disallow concurrent access to chat history

this.Logger.LogAgentChatInvokingAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokingAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

try
{
Expand All @@ -226,7 +226,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(

await foreach ((bool isVisible, ChatMessageContent message) in channel.InvokeAsync(agent, cancellationToken).ConfigureAwait(false))
{
this.Logger.LogAgentChatInvokedAgentMessage(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, message);
this.Logger.LogAgentChatInvokedAgentMessage(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName(), message);

messages.Add(message);

Expand All @@ -248,7 +248,7 @@ protected async IAsyncEnumerable<ChatMessageContent> InvokeAgentAsync(
.Select(kvp => new ChannelReference(kvp.Value, kvp.Key));
this._broadcastQueue.Enqueue(channelRefs, messages);

this.Logger.LogAgentChatInvokedAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokedAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());
}
finally
{
Expand All @@ -272,7 +272,7 @@ protected async IAsyncEnumerable<StreamingChatMessageContent> InvokeStreamingAge
{
this.SetActivityOrThrow(); // Disallow concurrent access to chat history

this.Logger.LogAgentChatInvokingAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokingAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

try
{
Expand All @@ -290,7 +290,7 @@ protected async IAsyncEnumerable<StreamingChatMessageContent> InvokeStreamingAge

this.History.AddRange(messages);

this.Logger.LogAgentChatInvokedStreamingAgentMessages(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, messages);
this.Logger.LogAgentChatInvokedStreamingAgentMessages(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName(), messages);

// Broadcast message to other channels (in parallel)
// Note: Able to queue messages without synchronizing channels.
Expand All @@ -300,7 +300,7 @@ protected async IAsyncEnumerable<StreamingChatMessageContent> InvokeStreamingAge
.Select(kvp => new ChannelReference(kvp.Value, kvp.Key));
this._broadcastQueue.Enqueue(channelRefs, messages);

this.Logger.LogAgentChatInvokedAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatInvokedAgent(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());
}
finally
{
Expand Down Expand Up @@ -433,7 +433,7 @@ private async Task<AgentChannel> GetOrCreateChannelAsync(Agent agent, Cancellati
AgentChannel? channel = await this.SynchronizeChannelAsync(channelKey, cancellationToken).ConfigureAwait(false);
if (channel is null)
{
this.Logger.LogAgentChatCreatingChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatCreatingChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

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

Expand All @@ -445,7 +445,7 @@ private async Task<AgentChannel> GetOrCreateChannelAsync(Agent agent, Cancellati
await channel.ReceiveAsync(this.History, cancellationToken).ConfigureAwait(false);
}

this.Logger.LogAgentChatCreatedChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentChatCreatedChannel(nameof(InvokeAgentAsync), agent.GetType(), agent.Id, agent.GetDisplayName());
}

return channel;
Expand Down
1 change: 1 addition & 0 deletions dotnet/src/Agents/Abstractions/Agents.Abstractions.csproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
<ItemGroup>
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/src/Diagnostics/*" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/src/System/AppContextSwitchHelper.cs" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/agents/Extensions/AgentExtensions.cs" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
</ItemGroup>

<ItemGroup>
Expand Down
46 changes: 27 additions & 19 deletions dotnet/src/Agents/Abstractions/Logging/AgentChatLogMessages.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
using System.Collections.Generic;
using System.Diagnostics.CodeAnalysis;
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel.Agents.Extensions;

namespace Microsoft.SemanticKernel.Agents;

Expand All @@ -21,25 +22,26 @@ 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>(
private static readonly Action<ILogger, string, string, string, string?, Exception?> s_logAgentChatGetChatMessages =
LoggerMessage.Define<string, string, string, string?>(
logLevel: LogLevel.Debug,
eventId: 0,
"[{MethodName}] Source: {MessageSourceType}/{MessageSourceId}.");
"[{MethodName}] Source: {MessageSourceType}/{MessageSourceId}/{MessageSourceName}.");

public static void LogAgentChatGetChatMessages(
this ILogger logger,
string methodName,
Agent? agent)
{
if (logger.IsEnabled(LogLevel.Debug))
{
if (null == agent)
if (agent is null)
{
s_logAgentChatGetChatMessages(logger, methodName, "primary", "primary", null);
s_logAgentChatGetChatMessages(logger, methodName, "primary", "primary", null, null);
}
else
{
s_logAgentChatGetChatMessages(logger, methodName, agent.GetType().Name, agent.Id, null);
s_logAgentChatGetChatMessages(logger, methodName, agent.GetType().Name, agent.Id, agent.GetDisplayName(), null);
}
}
}
Expand Down Expand Up @@ -74,48 +76,51 @@ public static partial void LogAgentChatAddedMessages(
[LoggerMessage(
EventId = 0,
Level = LogLevel.Debug,
Message = "[{MethodName}] Invoking agent {AgentType}/{AgentId}.")]
Message = "[{MethodName}] Invoking agent {AgentType}/{AgentId}/{AgentName}.")]
public static partial void LogAgentChatInvokingAgent(
this ILogger logger,
string methodName,
Type agentType,
string agentId);
string agentId,
string agentName);

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

/// <summary>
/// Logs retrieval of streamed <see cref="AgentChat"/> messages.
/// </summary>
private static readonly Action<ILogger, string, Type, string, ChatMessageContent, Exception?> s_logAgentChatInvokedStreamingAgentMessages =
LoggerMessage.Define<string, Type, string, ChatMessageContent>(
private static readonly Action<ILogger, string, Type, string, string, ChatMessageContent, Exception?> s_logAgentChatInvokedStreamingAgentMessages =
LoggerMessage.Define<string, Type, string, string, ChatMessageContent>(
logLevel: LogLevel.Debug,
eventId: 0,
"[{MethodName}] Agent message {AgentType}/{AgentId}: {Message}.");
"[{MethodName}] Agent message {AgentType}/{AgentId}/{AgentName}: {Message}.");

public static void LogAgentChatInvokedStreamingAgentMessages(
this ILogger logger,
string methodName,
Type agentType,
string agentId,
string agentName,
IList<ChatMessageContent> messages)
{
if (logger.IsEnabled(LogLevel.Debug))
{
foreach (ChatMessageContent message in messages)
{
s_logAgentChatInvokedStreamingAgentMessages(logger, methodName, agentType, agentId, message, null);
s_logAgentChatInvokedStreamingAgentMessages(logger, methodName, agentType, agentId, agentName, message, null);
}
}
}
Expand All @@ -126,36 +131,39 @@ public static void LogAgentChatInvokedStreamingAgentMessages(
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Invoked agent {AgentType}/{AgentId}.")]
Message = "[{MethodName}] Invoked agent {AgentType}/{AgentId}/{AgentName}.")]
public static partial void LogAgentChatInvokedAgent(
this ILogger logger,
string methodName,
Type agentType,
string agentId);
string agentId,
string agentName);

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

/// <summary>
/// Logs <see cref="AgentChat"/> created agent channel (complete).
/// </summary>
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "[{MethodName}] Created channel for {AgentType}: {AgentId}")]
Message = "[{MethodName}] Created channel for {AgentType}: {AgentId}/{AgentName}")]
public static partial void LogAgentChatCreatedChannel(
this ILogger logger,
string methodName,
Type agentType,
string agentId);
string agentId,
string agentName);
}
7 changes: 4 additions & 3 deletions dotnet/src/Agents/Core/AgentGroupChat.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.SemanticKernel.Agents.Chat;
using Microsoft.SemanticKernel.Agents.Extensions;

namespace Microsoft.SemanticKernel.Agents;

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

this.Logger.LogAgentGroupChatInvokingAgent(nameof(InvokeAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentGroupChatInvokingAgent(nameof(InvokeAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

this.AddAgent(agent);

Expand Down Expand Up @@ -163,7 +164,7 @@ public async IAsyncEnumerable<StreamingChatMessageContent> InvokeStreamingAsync(
{
this.EnsureStrategyLoggerAssignment();

this.Logger.LogAgentGroupChatInvokingAgent(nameof(InvokeAsync), agent.GetType(), agent.Id);
this.Logger.LogAgentGroupChatInvokingAgent(nameof(InvokeAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

this.AddAgent(agent);

Expand Down Expand Up @@ -255,7 +256,7 @@ private async Task<Agent> SelectAgentAsync(CancellationToken cancellationToken)
throw;
}

this.Logger.LogAgentGroupChatSelectedAgent(nameof(InvokeAsync), agent.GetType(), agent.Id, this.ExecutionSettings.SelectionStrategy.GetType());
this.Logger.LogAgentGroupChatSelectedAgent(nameof(InvokeAsync), agent.GetType(), agent.Id, agent.GetDisplayName(), this.ExecutionSettings.SelectionStrategy.GetType());

return agent;
}
Expand Down
1 change: 1 addition & 0 deletions dotnet/src/Agents/Core/Agents.Core.csproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/src/Diagnostics/*" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/src/System/TypeConverterFactory.cs" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/src/System/AppContextSwitchHelper.cs" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
<Compile Include="$(RepoRoot)/dotnet/src/InternalUtilities/agents/Extensions/AgentExtensions.cs" Link="%(RecursiveDir)Utilities/%(Filename)%(Extension)" />
</ItemGroup>

<ItemGroup>
Expand Down
3 changes: 2 additions & 1 deletion dotnet/src/Agents/Core/Chat/SequentialSelectionStrategy.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.SemanticKernel.Agents.Extensions;

namespace Microsoft.SemanticKernel.Agents.Chat;

Expand Down Expand Up @@ -42,7 +43,7 @@ protected override Task<Agent> SelectAgentAsync(IReadOnlyList<Agent> agents, IRe

Agent agent = agents[this._index];

this.Logger.LogSequentialSelectionStrategySelectedAgent(nameof(NextAsync), this._index, agents.Count, agent.Id);
this.Logger.LogSequentialSelectionStrategySelectedAgent(nameof(NextAsync), this._index, agents.Count, agent.Id, agent.GetDisplayName());

return Task.FromResult(agent);

Expand Down
7 changes: 4 additions & 3 deletions dotnet/src/Agents/Core/Chat/TerminationStrategy.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.SemanticKernel.Agents.Extensions;

namespace Microsoft.SemanticKernel.Agents.Chat;

Expand Down Expand Up @@ -55,19 +56,19 @@ public abstract class TerminationStrategy
/// <returns>True to terminate chat loop.</returns>
public async Task<bool> ShouldTerminateAsync(Agent agent, IReadOnlyList<ChatMessageContent> history, CancellationToken cancellationToken = default)
{
this.Logger.LogTerminationStrategyEvaluatingCriteria(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id);
this.Logger.LogTerminationStrategyEvaluatingCriteria(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

// `Agents` must contain `agent`, if `Agents` not empty.
if ((this.Agents?.Count ?? 0) > 0 && !this.Agents!.Any(a => a.Id == agent.Id))
{
this.Logger.LogTerminationStrategyAgentOutOfScope(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id);
this.Logger.LogTerminationStrategyAgentOutOfScope(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id, agent.GetDisplayName());

return false;
}

bool shouldTerminate = await this.ShouldAgentTerminateAsync(agent, history, cancellationToken).ConfigureAwait(false);

this.Logger.LogTerminationStrategyEvaluatedCriteria(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id, shouldTerminate);
this.Logger.LogTerminationStrategyEvaluatedCriteria(nameof(ShouldTerminateAsync), agent.GetType(), agent.Id, agent.GetDisplayName(), shouldTerminate);

return shouldTerminate;
}
Expand Down
9 changes: 5 additions & 4 deletions dotnet/src/Agents/Core/ChatCompletionAgent.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Text.Json;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.SemanticKernel.Agents.Extensions;
using Microsoft.SemanticKernel.ChatCompletion;
using Microsoft.SemanticKernel.Services;

Expand Down Expand Up @@ -59,7 +60,7 @@ public override async IAsyncEnumerable<ChatMessageContent> InvokeAsync(

int messageCount = chat.Count;

this.Logger.LogAgentChatServiceInvokingAgent(nameof(InvokeAsync), this.Id, chatCompletionService.GetType());
this.Logger.LogAgentChatServiceInvokingAgent(nameof(InvokeAsync), this.Id, this.GetDisplayName(), chatCompletionService.GetType());

IReadOnlyList<ChatMessageContent> messages =
await chatCompletionService.GetChatMessageContentsAsync(
Expand All @@ -68,7 +69,7 @@ await chatCompletionService.GetChatMessageContentsAsync(
kernel,
cancellationToken).ConfigureAwait(false);

this.Logger.LogAgentChatServiceInvokedAgent(nameof(InvokeAsync), this.Id, chatCompletionService.GetType(), messages.Count);
this.Logger.LogAgentChatServiceInvokedAgent(nameof(InvokeAsync), this.Id, this.GetDisplayName(), chatCompletionService.GetType(), messages.Count);

// Capture mutated messages related function calling / tools
for (int messageIndex = messageCount; messageIndex < chat.Count; messageIndex++)
Expand Down Expand Up @@ -104,7 +105,7 @@ public override async IAsyncEnumerable<StreamingChatMessageContent> InvokeStream

int messageCount = chat.Count;

this.Logger.LogAgentChatServiceInvokingAgent(nameof(InvokeAsync), this.Id, chatCompletionService.GetType());
this.Logger.LogAgentChatServiceInvokingAgent(nameof(InvokeAsync), this.Id, this.GetDisplayName(), chatCompletionService.GetType());

IAsyncEnumerable<StreamingChatMessageContent> messages =
chatCompletionService.GetStreamingChatMessageContentsAsync(
Expand All @@ -113,7 +114,7 @@ public override async IAsyncEnumerable<StreamingChatMessageContent> InvokeStream
kernel,
cancellationToken);

this.Logger.LogAgentChatServiceInvokedStreamingAgent(nameof(InvokeAsync), this.Id, chatCompletionService.GetType());
this.Logger.LogAgentChatServiceInvokedStreamingAgent(nameof(InvokeAsync), this.Id, this.GetDisplayName(), chatCompletionService.GetType());

AuthorRole? role = null;
StringBuilder builder = new();
Expand Down
Loading

0 comments on commit c311183

Please sign in to comment.