Skip to content

Commit 6654376

Browse files
westey-mwestey-m
authored
.Net: Add logging to AIContextProvider implementations (#12240)
### Motivation and Context It's important that AIContextProvider implementations have logging for important events that happen within them, so that users can use this to understand and troubleshoot what is happening #10100 ### Description - Add logging and unit tests for each provider. ### Contribution Checklist <!-- Before submitting this PR, please make sure: --> - [ ] The code builds clean without any errors or warnings - [ ] The PR follows the [SK Contribution Guidelines](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md) and the [pre-submission formatting script](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md#development-scripts) raises no violations - [ ] All unit tests pass, and I have added new tests where possible - [ ] I didn't break anyone 😄
1 parent ac5c37e commit 6654376

File tree

8 files changed

+212
-43
lines changed

8 files changed

+212
-43
lines changed

‎dotnet/samples/Concepts/Agents/ChatCompletion_Mem0.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ private async Task UseMemoryAsync()
3232
httpClient.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Token", TestConfiguration.Mem0.ApiKey);
3333

3434
// Create a mem0 component with the current user's id, so that it stores memories for that user.
35-
var mem0Provider = new Mem0Provider(httpClient, new()
35+
var mem0Provider = new Mem0Provider(httpClient, options: new()
3636
{
3737
UserId = "U1"
3838
});

‎dotnet/src/IntegrationTests/Memory/Mem0ProviderTests.cs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ public async Task CanAddAndRetrieveMemoriesAsync()
4646
var question = new ChatMessage(ChatRole.User, "What is my name?");
4747
var input = new ChatMessage(ChatRole.User, "Hello, my name is Caoimhe.");
4848

49-
var sut = new Mem0Provider(this._httpClient, new() { ThreadId = "test-thread-id", UserId = "test-user-id", ScopeToPerOperationThreadId = true });
49+
var sut = new Mem0Provider(this._httpClient, options: new() { ThreadId = "test-thread-id", UserId = "test-user-id", ScopeToPerOperationThreadId = true });
5050

5151
await sut.ClearStoredMemoriesAsync();
5252
var answerBeforeAdding = await sut.ModelInvokingAsync([question]);
@@ -73,7 +73,7 @@ public async Task CanAddAndRetrieveAgentMemoriesAsync()
7373
var question = new ChatMessage(ChatRole.User, "What is your name?");
7474
var input = new ChatMessage(ChatRole.Assistant, "Hello, I'm a friendly assistant and my name is Caoimhe.");
7575

76-
var sut = new Mem0Provider(this._httpClient, new() { AgentId = "test-agent-id" });
76+
var sut = new Mem0Provider(this._httpClient, options: new() { AgentId = "test-agent-id" });
7777

7878
await sut.ClearStoredMemoriesAsync();
7979
var answerBeforeAdding = await sut.ModelInvokingAsync([question]);
@@ -100,8 +100,8 @@ public async Task DoesNotLeakMessagesAcrossScopesAsync()
100100
var question = new ChatMessage(ChatRole.User, "What is your name?");
101101
var input = new ChatMessage(ChatRole.Assistant, "I'm an AI tutor with a personality. My name is Caoimhe.");
102102

103-
var sut1 = new Mem0Provider(this._httpClient, new() { AgentId = "test-agent-id-1" });
104-
var sut2 = new Mem0Provider(this._httpClient, new() { AgentId = "test-agent-id-2" });
103+
var sut1 = new Mem0Provider(this._httpClient, options: new() { AgentId = "test-agent-id-1" });
104+
var sut2 = new Mem0Provider(this._httpClient, options: new() { AgentId = "test-agent-id-2" });
105105

106106
await sut1.ClearStoredMemoriesAsync();
107107
await sut2.ClearStoredMemoriesAsync();
@@ -133,7 +133,7 @@ public async Task DoesNotWorkWithMultiplePerOperationThreadsAsync()
133133
// Arrange
134134
var input = new ChatMessage(ChatRole.User, "Hello, my name is Caoimhe.");
135135

136-
var sut = new Mem0Provider(this._httpClient, new() { UserId = "test-user-id", ScopeToPerOperationThreadId = true });
136+
var sut = new Mem0Provider(this._httpClient, options: new() { UserId = "test-user-id", ScopeToPerOperationThreadId = true });
137137

138138
await sut.ClearStoredMemoriesAsync();
139139

‎dotnet/src/SemanticKernel.Core/Data/TextSearchBehavior/TextSearchProvider.cs

Lines changed: 14 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
using System.Threading;
1111
using System.Threading.Tasks;
1212
using Microsoft.Extensions.AI;
13+
using Microsoft.Extensions.Logging;
1314

1415
namespace Microsoft.SemanticKernel.Data;
1516

@@ -25,20 +26,22 @@ public sealed class TextSearchProvider : AIContextProvider
2526
private const string DefaultIncludeCitationsPrompt = "Include citations to the source document with document name and link if document name and link is available.";
2627

2728
private readonly ITextSearch _textSearch;
28-
29+
private readonly ILogger<TextSearchProvider>? _logger;
2930
private readonly AIFunction[] _aIFunctions;
3031

3132
/// <summary>
3233
/// Initializes a new instance of the <see cref="TextSearchProvider"/> class.
3334
/// </summary>
3435
/// <param name="textSearch">The text search component to retrieve results from.</param>
36+
/// <param name="loggerFactory">The <see cref="ILoggerFactory"/> to use for logging. If null, no logging will be performed.</param>
3537
/// <param name="options">Options that configure the behavior of the component.</param>
3638
/// <exception cref="ArgumentNullException"></exception>
37-
public TextSearchProvider(ITextSearch textSearch, TextSearchProviderOptions? options = default)
39+
public TextSearchProvider(ITextSearch textSearch, ILoggerFactory? loggerFactory = default, TextSearchProviderOptions? options = default)
3840
{
3941
Verify.NotNull(textSearch);
4042

4143
this._textSearch = textSearch;
44+
this._logger = loggerFactory?.CreateLogger<TextSearchProvider>();
4245
this.Options = options ?? new();
4346

4447
this._aIFunctions =
@@ -77,7 +80,12 @@ public override async Task<AIContext> ModelInvokingAsync(ICollection<ChatMessage
7780

7881
var results = await searchResults.Results.ToListAsync(cancellationToken).ConfigureAwait(false);
7982

80-
return new() { Instructions = this.FormatResults(results) };
83+
var formatted = this.FormatResults(results);
84+
85+
this._logger?.LogInformation("TextSearchBehavior: Retrieved {Count} search results.", results.Count);
86+
this._logger?.LogTrace("TextSearchBehavior:\nInput Messages:{Input}\nOutput context instructions:\n{Instructions}", input, formatted);
87+
88+
return new() { Instructions = formatted };
8189
}
8290

8391
/// <summary>
@@ -93,7 +101,9 @@ internal async Task<string> SearchAsync(string userQuestion, CancellationToken c
93101

94102
var results = await searchResults.Results.ToListAsync(cancellationToken).ConfigureAwait(false);
95103

96-
return this.FormatResults(results);
104+
var formatted = this.FormatResults(results);
105+
106+
return formatted;
97107
}
98108

99109
/// <summary>

‎dotnet/src/SemanticKernel.Core/Memory/Mem0/Mem0Provider.cs

Lines changed: 17 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88
using System.Threading;
99
using System.Threading.Tasks;
1010
using Microsoft.Extensions.AI;
11+
using Microsoft.Extensions.Logging;
1112

1213
namespace Microsoft.SemanticKernel.Memory;
1314

@@ -48,11 +49,13 @@ public sealed class Mem0Provider : AIContextProvider
4849
private readonly string _contextPrompt;
4950

5051
private readonly Mem0Client _mem0Client;
52+
private readonly ILogger<Mem0Provider>? _logger;
5153

5254
/// <summary>
5355
/// Initializes a new instance of the <see cref="Mem0Provider"/> class.
5456
/// </summary>
5557
/// <param name="httpClient">The HTTP client used for making requests.</param>
58+
/// <param name="loggerFactory">The <see cref="ILoggerFactory"/> to use for logging. If null, no logging will be performed.</param>
5659
/// <param name="options">Options for configuring the component.</param>
5760
/// <remarks>
5861
/// The base address of the required mem0 service, and any authentication headers, should be set on the <paramref name="httpClient"/>
@@ -64,7 +67,7 @@ public sealed class Mem0Provider : AIContextProvider
6467
/// new Mem0Client(httpClient);
6568
/// </code>
6669
/// </remarks>
67-
public Mem0Provider(HttpClient httpClient, Mem0ProviderOptions? options = default)
70+
public Mem0Provider(HttpClient httpClient, ILoggerFactory? loggerFactory = default, Mem0ProviderOptions? options = default)
6871
{
6972
Verify.NotNull(httpClient);
7073

@@ -79,6 +82,7 @@ public Mem0Provider(HttpClient httpClient, Mem0ProviderOptions? options = defaul
7982
this._userId = options?.UserId;
8083
this._scopeToPerOperationThreadId = options?.ScopeToPerOperationThreadId ?? false;
8184
this._contextPrompt = options?.ContextPrompt ?? DefaultContextPrompt;
85+
this._logger = loggerFactory?.CreateLogger<Mem0Provider>();
8286

8387
this._mem0Client = new(httpClient);
8488
}
@@ -133,22 +137,31 @@ public override async Task<AIContext> ModelInvokingAsync(ICollection<ChatMessage
133137
Where(m => m is not null && !string.IsNullOrWhiteSpace(m.Text)).
134138
Select(m => m.Text));
135139

136-
var memories = await this._mem0Client.SearchAsync(
140+
var memories = (await this._mem0Client.SearchAsync(
137141
this._applicationId,
138142
this._agentId,
139143
this._scopeToPerOperationThreadId ? this._perOperationThreadId : this._threadId,
140144
this._userId,
141-
inputText).ConfigureAwait(false);
145+
inputText).ConfigureAwait(false)).ToList();
142146

143147
var lineSeparatedMemories = string.Join(Environment.NewLine, memories);
144-
return new()
148+
149+
var context = new AIContext
145150
{
146151
Instructions =
147152
$"""
148153
{this._contextPrompt}
149154
{lineSeparatedMemories}
150155
"""
151156
};
157+
158+
if (this._logger != null)
159+
{
160+
this._logger.LogInformation("Mem0Behavior: Retrieved {Count} memories from mem0.", memories.Count);
161+
this._logger.LogTrace("Mem0Behavior:\nInput messages:{Input}\nOutput context instructions:\n{Instructions}", inputText, context.Instructions);
162+
}
163+
164+
return context;
152165
}
153166

154167
/// <summary>

‎dotnet/src/SemanticKernel.Core/Memory/Whiteboard/WhiteboardProvider.cs

Lines changed: 24 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
using System.Threading;
1212
using System.Threading.Tasks;
1313
using Microsoft.Extensions.AI;
14+
using Microsoft.Extensions.Logging;
1415

1516
namespace Microsoft.SemanticKernel.Memory;
1617

@@ -31,6 +32,7 @@ public sealed class WhiteboardProvider : AIContextProvider
3132
private readonly string _maintenancePrompt;
3233

3334
private readonly IChatClient _chatClient;
35+
private readonly ILogger? _logger;
3436

3537
private List<string> _currentWhiteboardContent = [];
3638

@@ -42,8 +44,9 @@ public sealed class WhiteboardProvider : AIContextProvider
4244
/// Initializes a new instance of the <see cref="WhiteboardProvider"/> class.
4345
/// </summary>
4446
/// <param name="chatClient">A <see cref="IChatClient"/> to use for making chat completion calls.</param>
47+
/// <param name="loggerFactory">The <see cref="ILoggerFactory"/> to use for logging. If null, no logging will be performed.</param>
4548
/// <param name="options">Options for configuring the provider.</param>
46-
public WhiteboardProvider(IChatClient chatClient, WhiteboardProviderOptions? options = default)
49+
public WhiteboardProvider(IChatClient chatClient, ILoggerFactory? loggerFactory = default, WhiteboardProviderOptions? options = default)
4750
{
4851
Verify.NotNull(chatClient);
4952

@@ -52,6 +55,7 @@ public WhiteboardProvider(IChatClient chatClient, WhiteboardProviderOptions? opt
5255
this._contextPrompt = options?.ContextPrompt ?? DefaultContextPrompt;
5356
this._whiteboardEmptyPrompt = options?.WhiteboardEmptyPrompt ?? DefaultWhiteboardEmptyPrompt;
5457
this._maintenancePrompt = options?.MaintenancePromptTemplate ?? MaintenancePromptTemplate;
58+
this._logger = loggerFactory?.CreateLogger<WhiteboardProvider>();
5559
}
5660

5761
/// <summary>
@@ -94,16 +98,26 @@ public override async Task MessageAddingAsync(string? conversationId, ChatMessag
9498
/// <inheritdoc/>
9599
public override Task<AIContext> ModelInvokingAsync(ICollection<ChatMessage> newMessages, CancellationToken cancellationToken = default)
96100
{
97-
if (this._currentWhiteboardContent.Count == 0)
101+
// Take a reference to the current whiteboard to avoid inconsistent logging and results
102+
// if it's updated during this method's execution.
103+
var currentWhiteboard = this._currentWhiteboardContent;
104+
105+
if (currentWhiteboard.Count == 0)
98106
{
107+
this._logger?.LogTrace("WhiteboardBehavior: Output context instructions:\n{Context}", this._whiteboardEmptyPrompt);
99108
return Task.FromResult(new AIContext() { Instructions = this._whiteboardEmptyPrompt });
100109
}
101110

102-
var numberedMessages = this._currentWhiteboardContent.Select((x, i) => $"{i} {x}");
111+
var numberedMessages = currentWhiteboard.Select((x, i) => $"{i} {x}");
103112
var joinedMessages = string.Join(Environment.NewLine, numberedMessages);
113+
var context = $"{this._contextPrompt}\n{joinedMessages}";
114+
115+
this._logger?.LogInformation("WhiteboardBehavior: Whiteboard contains {Count} messages.", currentWhiteboard.Count);
116+
this._logger?.LogTrace("WhiteboardBehavior: Output context instructions:\n{Context}", context);
117+
104118
return Task.FromResult(new AIContext()
105119
{
106-
Instructions = $"{this._contextPrompt}\n{joinedMessages}"
120+
Instructions = context
107121
});
108122
}
109123

@@ -155,6 +169,12 @@ private async Task UpdateWhiteboardAsync(ChatMessage newMessage, CancellationTok
155169
// Update the current whiteboard content with the LLM result.
156170
var newWhiteboardResponse = JsonSerializer.Deserialize(result.ToString(), WhiteboardProviderSourceGenerationContext.Default.NewWhiteboardResponse);
157171
this._currentWhiteboardContent = newWhiteboardResponse?.NewWhiteboard ?? [];
172+
173+
this._logger?.LogTrace(
174+
"WhiteboardBehavior: Updated whiteboard.\nInputMessages:\n{InputMessagesJson}\nCurrentWhiteboard:\n{CurrentWhiteboardJson}\nNew Whiteboard:\n{NewWhiteboard}",
175+
inputMessagesJson,
176+
currentWhiteboardJson,
177+
result);
158178
}
159179

160180
private string FormatPromptTemplate(string inputMessagesJson, string currentWhiteboardJson, int maxWhiteboardMessages)

‎dotnet/src/SemanticKernel.UnitTests/Data/TextSearchProviderTests.cs

Lines changed: 49 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,12 @@
11
// Copyright (c) Microsoft. All rights reserved.
22

3+
using System;
34
using System.Collections.Generic;
45
using System.Linq;
56
using System.Threading;
67
using System.Threading.Tasks;
78
using Microsoft.Extensions.AI;
9+
using Microsoft.Extensions.Logging;
810
using Microsoft.SemanticKernel.Data;
911
using Moq;
1012
using Xunit;
@@ -16,14 +18,30 @@ namespace SemanticKernel.UnitTests.Data;
1618
/// </summary>
1719
public class TextSearchProviderTests
1820
{
21+
private readonly Mock<ILogger<TextSearchProvider>> _loggerMock;
22+
private readonly Mock<ILoggerFactory> _loggerFactoryMock;
23+
24+
public TextSearchProviderTests()
25+
{
26+
this._loggerMock = new();
27+
this._loggerFactoryMock = new();
28+
this._loggerFactoryMock
29+
.Setup(f => f.CreateLogger(It.IsAny<string>()))
30+
.Returns(this._loggerMock.Object);
31+
this._loggerFactoryMock
32+
.Setup(f => f.CreateLogger(typeof(TextSearchProvider).FullName!))
33+
.Returns(this._loggerMock.Object);
34+
}
35+
1936
[Theory]
20-
[InlineData(null, null, "Consider the following information from source documents when responding to the user:", "Include citations to the source document with document name and link if document name and link is available.")]
21-
[InlineData("Custom context prompt", "Custom citations prompt", "Custom context prompt", "Custom citations prompt")]
37+
[InlineData(null, null, "Consider the following information from source documents when responding to the user:", "Include citations to the source document with document name and link if document name and link is available.", true)]
38+
[InlineData("Custom context prompt", "Custom citations prompt", "Custom context prompt", "Custom citations prompt", false)]
2239
public async Task ModelInvokingShouldIncludeSearchResultsInOutputAsync(
2340
string? overrideContextPrompt,
2441
string? overrideCitationsPrompt,
2542
string expectedContextPrompt,
26-
string expectedCitationsPrompt)
43+
string expectedCitationsPrompt,
44+
bool withLogging)
2745
{
2846
// Arrange
2947
var mockTextSearch = new Mock<ITextSearch>();
@@ -63,7 +81,10 @@ public async Task ModelInvokingShouldIncludeSearchResultsInOutputAsync(
6381
IncludeCitationsPrompt = overrideCitationsPrompt
6482
};
6583

66-
var component = new TextSearchProvider(mockTextSearch.Object, options);
84+
var component = new TextSearchProvider(
85+
mockTextSearch.Object,
86+
withLogging ? this._loggerFactoryMock.Object : null,
87+
options: options);
6788

6889
// Act
6990
var result = await component.ModelInvokingAsync([new ChatMessage(ChatRole.User, "Sample user question?")], CancellationToken.None);
@@ -77,6 +98,27 @@ public async Task ModelInvokingShouldIncludeSearchResultsInOutputAsync(
7798
Assert.Contains("SourceDocLink: http://example.com/doc2", result.Instructions);
7899
Assert.Contains("Contents: Content of Doc2", result.Instructions);
79100
Assert.Contains(expectedCitationsPrompt, result.Instructions);
101+
102+
if (withLogging)
103+
{
104+
this._loggerMock.Verify(
105+
l => l.Log(
106+
LogLevel.Information,
107+
It.IsAny<EventId>(),
108+
It.Is<It.IsAnyType>((v, t) => v.ToString()!.Contains("TextSearchBehavior: Retrieved 2 search results.")),
109+
It.IsAny<Exception?>(),
110+
It.IsAny<Func<It.IsAnyType, Exception?, string>>()),
111+
Times.AtLeastOnce);
112+
113+
this._loggerMock.Verify(
114+
l => l.Log(
115+
LogLevel.Trace,
116+
It.IsAny<EventId>(),
117+
It.Is<It.IsAnyType>((v, t) => v.ToString()!.Contains("TextSearchBehavior:\nInput Messages:Sample user question?\nOutput context instructions:") && v.ToString()!.Contains("SourceDocName: Doc1") && v.ToString()!.Contains("SourceDocName: Doc2")),
118+
It.IsAny<Exception?>(),
119+
It.IsAny<Func<It.IsAnyType, Exception?, string>>()),
120+
Times.AtLeastOnce);
121+
}
80122
}
81123

82124
[Theory]
@@ -97,7 +139,7 @@ public async Task AIFunctionsShouldBeRegisteredCorrectly(
97139
PluginFunctionDescription = overridePluginFunctionDescription
98140
};
99141

100-
var component = new TextSearchProvider(mockTextSearch.Object, options);
142+
var component = new TextSearchProvider(mockTextSearch.Object, options: options);
101143

102144
// Act
103145
var aiContextAdditions = await component.ModelInvokingAsync([new ChatMessage(ChatRole.User, "Sample user question?")], CancellationToken.None);
@@ -157,7 +199,7 @@ public async Task SearchAsyncShouldIncludeSearchResultsInOutputAsync(
157199
IncludeCitationsPrompt = overrideCitationsPrompt
158200
};
159201

160-
var component = new TextSearchProvider(mockTextSearch.Object, options);
202+
var component = new TextSearchProvider(mockTextSearch.Object, options: options);
161203

162204
// Act
163205
var result = await component.SearchAsync("Sample user question?", CancellationToken.None);
@@ -213,7 +255,7 @@ public async Task ModelInvokingShouldUseOverrideContextFormatterIfProvidedAsync(
213255
ContextFormatter = results => $"Custom formatted context with {results.Count} results."
214256
};
215257

216-
var component = new TextSearchProvider(mockTextSearch.Object, options);
258+
var component = new TextSearchProvider(mockTextSearch.Object, options: options);
217259

218260
// Act
219261
var result = await component.ModelInvokingAsync([new ChatMessage(ChatRole.User, "Sample user question?")], CancellationToken.None);

0 commit comments

Comments
 (0)