microsoft/semantic-kernel
1
0
Fork 0
mirror of https://github.com/microsoft/semantic-kernel.git synced 2026-10-12 02:19:06 +00:00
Code Issues Packages Projects Releases Wiki Activity

.Net: SK Telemetry improvements (#1905)

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

This PR contains changes to improve observability for Semantic Kernel
users, including:
- Logging: using already existing `ILogger` interface with some
improvements described below.
- Metering: implemented using `Meter` and `MeterListener` classes from
`System.Diagnostics.Metrics` namespace.
- Tracing: implemented using `Activity`, `ActivitySource` and
`ActivityListener` classes from `System.Diagnostics` namespace.

Added telemetry uses native .NET methods, which means that it's not
dependent on specific telemetry tool.
Current PR contains console application using Application Insights as
example to show telemetry capabilities in Kernel.

Changes include instrumentation for `SequentialPlanner` as a starting
point and later there will be new PRs for other types of planners and
more improvements for kernel telemetry.

Also, there are updates for `LogLevel` handling across codebase to align
with described log level purpose:

https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.loglevel?view=dotnet-plat-ext-7.0

Particularly, there are changes for `LogLevel.Trace` to be used for
sensitive data and most detailed messages, which should not be enabled
in prodution environments.

### Description
<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->
Changes:
- Marked `.WithLogger` method in KernelBuilder as obsolete and added new
method `.WithLogging`.
- Added new methods `.WithMetering` and `.WithTracing` in KernelBuilder.
- Improved `LogLevel` handling across codebase to cover cases of logging
sensitive data.
- Implemented `InstrumentedSequentialPlanner` for instrumentation using
decorator pattern.
- Extended `InvokeAsync` method in `Plan` for instrumentation.

### Contribution Checklist
<!-- Before submitting this PR, please make sure: -->
- [x] The code builds clean without any errors or warnings
- [x] The PR follows SK Contribution Guidelines
(https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md)
- [x] The code follows the .NET coding conventions
(https://learn.microsoft.com/dotnet/csharp/fundamentals/coding-style/coding-conventions)
verified with `dotnet format`
- [x] All unit tests pass, and I have added new tests where possible
- [x] I didn't break anyone 😄

---------

Co-authored-by: Shawn Callegari <[email protected]>
This commit is contained in:
Dmytro Struk
2023-07-18 20:36:37 +00:00
committed by GitHub
co-authored by Shawn Callegari
parent f622bfeb88
commit 55dc7942e5
45 changed files with 742 additions and 131 deletions
Download Patch File Download Diff File Expand all files Collapse all files
dotnet/Directory.Packages.props
+2
View File
@@ -8,12 +8,14 @@
<PackageVersion Include="Azure.AI.OpenAI" Version="1.0.0-beta.5" />
<PackageVersion Include="Azure.Identity" Version="1.9.0" />
<PackageVersion Include="Azure.Search.Documents" Version="11.5.0-beta.3" />
<PackageVersion Include="Microsoft.ApplicationInsights.WorkerService" Version="2.21.0" />
<PackageVersion Include="Microsoft.Bcl.HashCode" Version="[1.1.0, )" />
<PackageVersion Include="Microsoft.Bcl.AsyncInterfaces" Version="6.0.0" />
<PackageVersion Include="Microsoft.Extensions.Http" Version="6.0.0" />
<PackageVersion Include="NRedisStack" Version="0.8.0" />
<PackageVersion Include="Pgvector" Version="0.1.3" />
<PackageVersion Include="Polly" Version="7.2.4" />
<PackageVersion Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />
<PackageVersion Include="System.Linq.Async" Version="6.0.1" />
<PackageVersion Include="System.Text.Json" Version="6.0.8" />
<!-- Microsoft.Extensions.Logging -->
dotnet/SK-dotnet.sln
+9
View File
@@ -145,6 +145,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Connectors.AI.Oobabooga", "
EndProject
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Planning.StepwisePlanner", "src\Extensions\Planning.StepwisePlanner\Planning.StepwisePlanner.csproj", "{4762BCAF-E1C5-4714-B88D-E50FA333C50E}"
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ApplicationInsightsExample", "samples\ApplicationInsightsExample\ApplicationInsightsExample.csproj", "{C754950A-E16C-4F96-9CC7-9328E361B5AF}"
EndProject
Global
GlobalSection(SolutionConfigurationPlatforms) = preSolution
Debug|Any CPU = Debug|Any CPU
@@ -356,6 +358,12 @@ Global
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Publish|Any CPU.Build.0 = Publish|Any CPU
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Release|Any CPU.ActiveCfg = Release|Any CPU
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Release|Any CPU.Build.0 = Release|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Debug|Any CPU.Build.0 = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Publish|Any CPU.ActiveCfg = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Publish|Any CPU.Build.0 = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Release|Any CPU.ActiveCfg = Release|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Release|Any CPU.Build.0 = Release|Any CPU
EndGlobalSection
GlobalSection(SolutionProperties) = preSolution
HideSolutionNode = FALSE
@@ -407,6 +415,7 @@ Global
{E6EDAB8F-3406-4DBF-9AAB-DF40DC2CA0FA} = {FA3720F1-C99A-49B2-9577-A940257098BF}
{677F1381-7830-4115-9C1A-58B282629DC6} = {0247C2C9-86C3-45BA-8873-28B0948EDC0C}
{4762BCAF-E1C5-4714-B88D-E50FA333C50E} = {078F96B4-09E1-4E0E-B214-F71A4F4BF633}
{C754950A-E16C-4F96-9CC7-9328E361B5AF} = {FA3720F1-C99A-49B2-9577-A940257098BF}
EndGlobalSection
GlobalSection(ExtensibilityGlobals) = postSolution
SolutionGuid = {FBDC56A3-86AD-4323-AA0F-201E59123B83}
dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj
+27
View File
@@ -0,0 +1,27 @@
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<TargetFramework>net6.0</TargetFramework>
<RollForward>LatestMajor</RollForward>
<OutputType>Exe</OutputType>
<LangVersion>10</LangVersion>
<Nullable>enable</Nullable>
<ImplicitUsings>disable</ImplicitUsings>
<IsPackable>false</IsPackable>
<!-- Suppress: "Declare types in namespaces", "Require ConfigureAwait" -->
<NoWarn>CA1050;CA1707;CA2007;VSTHRD111</NoWarn>
<UserSecretsId>5ee045b0-aea3-4f08-8d31-32d1a6f8fed0</UserSecretsId>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="Microsoft.ApplicationInsights.WorkerService" />
<PackageReference Include="Microsoft.Extensions.Configuration.UserSecrets" />
</ItemGroup>
<ItemGroup>
<ProjectReference Include="..\..\src\Extensions\Planning.SequentialPlanner\Planning.SequentialPlanner.csproj" />
<ProjectReference Include="..\..\src\Connectors\Connectors.AI.OpenAI\Connectors.AI.OpenAI.csproj" />
<ProjectReference Include="..\..\src\SemanticKernel\SemanticKernel.csproj" />
</ItemGroup>
</Project>
dotnet/samples/ApplicationInsightsExample/Program.cs
+192
View File
@@ -0,0 +1,192 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using System.Collections.Concurrent;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using System.Threading.Tasks;
using Microsoft.ApplicationInsights;
using Microsoft.ApplicationInsights.DataContracts;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.ApplicationInsights;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Planning;
using Microsoft.SemanticKernel.Planning.Sequential;
/// <summary>
/// Example of telemetry in Semantic Kernel using Application Insights within console application.
/// </summary>
public sealed class Program
{
/// <summary>
/// Log level to be used by <see cref="ILogger"/>.
/// </summary>
/// <remarks>
/// <see cref="LogLevel.Information"/> is set by default. <para />
/// <see cref="LogLevel.Trace"/> will enable logging with more detailed information, including sensitive data. Should not be used in production. <para />
/// </remarks>
private static LogLevel LogLevel = LogLevel.Information;
public static async Task Main()
{
var serviceProvider = GetServiceProvider();
var telemetryClient = serviceProvider.GetRequiredService<TelemetryClient>();
var logger = serviceProvider.GetRequiredService<ILogger<Program>>();
using var meterListener = new MeterListener();
using var activityListener = new ActivityListener();
ConfigureMetering(meterListener, telemetryClient);
ConfigureTracing(activityListener, telemetryClient);
var kernel = GetKernel(logger);
var planner = GetPlanner(kernel, logger);
try
{
using var operation = telemetryClient.StartOperation<DependencyTelemetry>("ApplicationInsights.Example");
Console.WriteLine("Operation/Trace ID:");
Console.WriteLine(Activity.Current?.TraceId);
var plan = await planner.CreatePlanAsync("Write a poem about John Doe, then translate it into Italian.");
Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
var result = await kernel.RunAsync(plan);
Console.WriteLine("Result:");
Console.WriteLine(result.Result);
}
finally
{
// Explicitly call Flush() followed by sleep is required in console apps.
// This is to ensure that even if application terminates, telemetry is sent to the back-end.
telemetryClient.Flush();
await Task.Delay(5000);
}
}
private static ServiceProvider GetServiceProvider()
{
var services = new ServiceCollection();
ConfigureApplicationInsightsTelemetry(services);
return services.BuildServiceProvider();
}
private static void ConfigureApplicationInsightsTelemetry(ServiceCollection services)
{
string instrumentationKey = Env.Var("ApplicationInsights__InstrumentationKey");
services.AddLogging(loggingBuilder =>
{
loggingBuilder.AddFilter<ApplicationInsightsLoggerProvider>(typeof(Program).FullName, LogLevel);
loggingBuilder.SetMinimumLevel(LogLevel);
});
services.AddApplicationInsightsTelemetryWorkerService(options =>
{
options.ConnectionString = $"InstrumentationKey={instrumentationKey}";
});
}
private static IKernel GetKernel(ILogger logger)
{
string folder = RepoFiles.SampleSkillsPath();
var kernel = new KernelBuilder()
.WithLogger(logger)
.WithAzureChatCompletionService(
Env.Var("AzureOpenAI__ChatDeploymentName"),
Env.Var("AzureOpenAI__Endpoint"),
Env.Var("AzureOpenAI__ApiKey"))
.Build();
kernel.ImportSemanticSkillFromDirectory(folder, "SummarizeSkill", "WriterSkill");
return kernel;
}
private static ISequentialPlanner GetPlanner(
IKernel kernel,
ILogger logger,
int maxTokens = 1024)
{
var plannerConfig = new SequentialPlannerConfig { MaxTokens = maxTokens };
return new SequentialPlanner(kernel, plannerConfig).WithInstrumentation(logger);
}
/// <summary>
/// Example of metering configuration in Application Insights
/// using <see cref="MeterListener"/> to attach for <see cref="Meter"/> recordings.
/// </summary>
/// <param name="meterListener">Instance of <see cref="MeterListener"/> for metering configuration.</param>
/// <param name="telemetryClient">Instance of Application Insights <see cref="TelemetryClient"/>.</param>
private static void ConfigureMetering(MeterListener meterListener, TelemetryClient telemetryClient)
{
meterListener.InstrumentPublished = (instrument, listener) =>
{
// Subscribe to all metrics in Semantic Kernel
if (instrument.Meter.Name.StartsWith("Microsoft.SemanticKernel", StringComparison.Ordinal))
{
listener.EnableMeasurementEvents(instrument);
}
};
MeasurementCallback<double> measurementCallback = (instrument, measurement, tags, state) =>
{
telemetryClient.GetMetric(instrument.Name).TrackValue(measurement);
};
meterListener.SetMeasurementEventCallback(measurementCallback);
meterListener.Start();
}
/// <summary>
/// Example of advanced distributed tracing configuration in Application Insights
/// using <see cref="ActivityListener"/> to attach for <see cref="Activity"/> events.
/// </summary>
/// <param name="activityListener">Instance of <see cref="ActivityListener"/> for tracing configuration.</param>
/// <param name="telemetryClient">Instance of Application Insights <see cref="TelemetryClient"/>.</param>
private static void ConfigureTracing(ActivityListener activityListener, TelemetryClient telemetryClient)
{
var operations = new ConcurrentDictionary<string, IOperationHolder<DependencyTelemetry>>();
// For more detailed tracing we need to attach Activity entity to Application Insights operation manually.
Action<Activity> activityStarted = activity =>
{
var operation = telemetryClient.StartOperation<DependencyTelemetry>(activity);
operation.Telemetry.Type = activity.Kind.ToString();
operations.TryAdd(activity.TraceId.ToString(), operation);
};
// We also need to manually stop Application Insights operation when Activity entity is stopped.
Action<Activity> activityStopped = activity =>
{
if (operations.TryRemove(activity.TraceId.ToString(), out var operation))
{
telemetryClient.StopOperation(operation);
}
};
// Subscribe to all traces in Semantic Kernel
activityListener.ShouldListenTo =
activitySource => activitySource.Name.StartsWith("Microsoft.SemanticKernel", StringComparison.Ordinal);
activityListener.Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData;
activityListener.SampleUsingParentId = (ref ActivityCreationOptions<string> _) => ActivitySamplingResult.AllData;
activityListener.ActivityStarted = activityStarted;
activityListener.ActivityStopped = activityStopped;
ActivitySource.AddActivityListener(activityListener);
}
}
dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs
+36
View File
@@ -0,0 +1,36 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using Microsoft.Extensions.Configuration;
#pragma warning disable CA1812 // instantiated by AddUserSecrets
internal sealed class Env
#pragma warning restore CA1812
{
/// <summary>
/// Simple helper used to load env vars and secrets like credentials,
/// to avoid hard coding them in the sample code
/// </summary>
/// <param name="name">Secret name / Env var name</param>
/// <returns>Value found in Secret Manager or Environment Variable</returns>
internal static string Var(string name)
{
var configuration = new ConfigurationBuilder()
.AddUserSecrets<Env>()
.Build();
var value = configuration[name];
if (!string.IsNullOrEmpty(value))
{
return value;
}
value = Environment.GetEnvironmentVariable(name);
if (string.IsNullOrEmpty(value))
{
throw new ArgumentException($"Secret / Env var not set: {name}");
}
return value;
}
}
dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs
+39
View File
@@ -0,0 +1,39 @@
// Copyright (c) Microsoft. All rights reserved.
using System.IO;
using System.Reflection;
internal static class RepoFiles
{
/// <summary>
/// Scan the local folders from the repo, looking for "samples/skills" folder.
/// </summary>
/// <returns>The full path to samples/skills</returns>
public static string SampleSkillsPath()
{
const string Parent = "samples";
const string Folder = "skills";
bool SearchPath(string pathToFind, out string result, int maxAttempts = 10)
{
var currDir = Path.GetFullPath(Assembly.GetExecutingAssembly().Location);
bool found;
do
{
result = Path.Join(currDir, pathToFind);
found = Directory.Exists(result);
currDir = Path.GetFullPath(Path.Combine(currDir, ".."));
} while (maxAttempts-- > 0 && !found);
return found;
}
if (!SearchPath(Parent + Path.DirectorySeparatorChar + Folder, out string path)
&& !SearchPath(Folder, out path))
{
throw new DirectoryNotFoundException("Skills directory not found. The app needs the skills from the repo to work.");
}
return path;
}
}
dotnet/samples/KernelSyntaxExamples/Example12_SequentialPlanner.cs
+4 -4
View File
@@ -92,7 +92,7 @@ internal static class Example12_SequentialPlanner
// - WriterSkill.Translate language='Italian' INPUT='' =>
Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
var result = await kernel.RunAsync(plan);
@@ -124,7 +124,7 @@ internal static class Example12_SequentialPlanner
// - email.SendEmail INPUT='$TRANSLATED_SUMMARY' email_address='$EMAIL_ADDRESS' =>
Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
var input =
"Once upon a time, in a faraway kingdom, there lived a kind and just king named Arjun. " +
@@ -166,7 +166,7 @@ internal static class Example12_SequentialPlanner
// - WriterSkill.NovelChapter chapterIndex='3' previousChapter='$CHAPTER_2_SYNOPSIS' INPUT='$CHAPTER_3_SYNOPSIS' theme='Children's mystery' => RESULT__CHAPTER_3
Console.WriteLine("Original plan:");
Console.WriteLine(originalPlan.ToPlanString());
Console.WriteLine(originalPlan.ToPlanWithGoalString());
Stopwatch sw = new();
sw.Start();
@@ -215,7 +215,7 @@ internal static class Example12_SequentialPlanner
var plan = await planner.CreatePlanAsync(goal);
Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
}
private static IKernel InitializeKernelAndPlanner(out SequentialPlanner planner, int maxTokens = 1024)
dotnet/samples/KernelSyntaxExamples/Example31_CustomPlanner.cs
+1 -1
View File
@@ -147,7 +147,7 @@ public class MarkupSkill
var plan = docString.FromMarkup("Run a piece of xml markup", context);
Console.WriteLine("Markup plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
Console.WriteLine();
var result = await plan.InvokeAsync();
dotnet/samples/KernelSyntaxExamples/Example48_GroundednessChecks.cs
+1 -1
View File
@@ -141,7 +141,7 @@ which are not grounded in the original.
var plannerConfig = new SequentialPlannerConfig { };
var planner = new SequentialPlanner(kernel, plannerConfig);
var plan = await planner.CreatePlanAsync(ask);
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
var results = await plan.InvokeAsync(s_groundingText);
Console.WriteLine(results.Result);
dotnet/samples/KernelSyntaxExamples/RepoUtils/PlanExtensions.cs
+3 -29
View File
@@ -1,41 +1,15 @@
// Copyright (c) Microsoft. All rights reserved.
using System.Linq;
using Microsoft.SemanticKernel.Planning;
namespace RepoUtils;
internal static class PlanExtensions
{
internal static string ToPlanString(this Plan originalPlan, string indent = " ")
internal static string ToPlanWithGoalString(this Plan plan, string indent = " ")
{
string goalHeader = $"{indent}Goal: {originalPlan.Description}\n\n{indent}Steps:\n";
string goalHeader = $"{indent}Goal: {plan.Description}\n\n{indent}Steps:\n";
string stepItems = string.Join("\n", originalPlan.Steps.Select(step =>
{
if (step.Steps.Count == 0)
{
string skillName = step.SkillName;
string stepName = step.Name;
string parameters = string.Join(" ", step.Parameters.Select(param => $"{param.Key}='{param.Value}'"));
if (!string.IsNullOrEmpty(parameters))
{
parameters = $" {parameters}";
}
string? outputs = step.Outputs.FirstOrDefault();
if (!string.IsNullOrEmpty(outputs))
{
outputs = $" => {outputs}";
}
return $"{indent}{indent}- {string.Join(".", skillName, stepName)}{parameters}{outputs}";
}
return step.ToPlanString(indent + indent);
}));
return goalHeader + stepItems;
return goalHeader + plan.ToPlanString();
}
}
dotnet/samples/KernelSyntaxExamples/Skills/EmailSkill.cs
+3 -1
View File
@@ -20,7 +20,9 @@ internal sealed class EmailSkill
[Description("The name of the person whose email address needs to be found.")] string input,
ILogger? logger = null)
{
logger?.LogDebug("Returning hard coded email for {0}", input);
// Sensitive data, logging as trace, disabled by default
logger?.LogTrace("Returning hard coded email for {0}", input);
return "[email protected]";
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/AzureOpenAIClientBase.cs
+12 -2
View File
@@ -2,6 +2,7 @@
using System;
using System.Net.Http;
using System.Runtime.CompilerServices;
using Azure;
using Azure.AI.OpenAI;
using Azure.Core;
@@ -31,7 +32,7 @@ public abstract class AzureOpenAIClientBase : ClientBase
string endpoint,
string apiKey,
HttpClient? httpClient = null,
ILogger? logger = null)
ILogger? logger = null) : base(logger)
{
Verify.NotNullOrWhiteSpace(modelId);
Verify.NotNullOrWhiteSpace(endpoint);
@@ -62,7 +63,7 @@ public abstract class AzureOpenAIClientBase : ClientBase
string endpoint,
TokenCredential credential,
HttpClient? httpClient = null,
ILogger? logger = null)
ILogger? logger = null) : base(logger)
{
Verify.NotNullOrWhiteSpace(modelId);
Verify.NotNullOrWhiteSpace(endpoint);
@@ -95,4 +96,13 @@ public abstract class AzureOpenAIClientBase : ClientBase
this.ModelId = modelId;
this.Client = openAIClient;
}
/// <summary>
/// Logs Azure OpenAI action details.
/// </summary>
/// <param name="callerMemberName">Caller member name. Populated automatically by runtime.</param>
private protected void LogActionDetails([CallerMemberName] string? callerMemberName = default)
{
this.Logger.LogInformation("Action: {Action}. Azure OpenAI Deployment Name: {DeploymentName}.", callerMemberName, this.ModelId);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/ClientBase.cs
+11 -1
View File
@@ -8,6 +8,8 @@ using System.Threading;
using System.Threading.Tasks;
using Azure;
using Azure.AI.OpenAI;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.SemanticKernel.AI;
using Microsoft.SemanticKernel.AI.ChatCompletion;
using Microsoft.SemanticKernel.AI.Embeddings;
@@ -25,7 +27,10 @@ public abstract class ClientBase
private const int MaxResultsPerPrompt = 128;
// Prevent external inheritors
private protected ClientBase() { }
private protected ClientBase(ILogger? logger = null)
{
this.Logger = logger ?? NullLogger.Instance;
}
/// <summary>
/// Model Id or Deployment Name
@@ -37,6 +42,11 @@ public abstract class ClientBase
/// </summary>
private protected abstract OpenAIClient Client { get; }
/// <summary>
/// Logger instance
/// </summary>
private protected ILogger Logger { get; set; }
/// <summary>
/// Creates completions for the prompt and settings.
/// </summary>
dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/OpenAIClientBase.cs
+11 -1
View File
@@ -1,6 +1,7 @@
// Copyright (c) Microsoft. All rights reserved.
using System.Net.Http;
using System.Runtime.CompilerServices;
using Azure.AI.OpenAI;
using Azure.Core;
using Azure.Core.Pipeline;
@@ -29,7 +30,7 @@ public abstract class OpenAIClientBase : ClientBase
string apiKey,
string? organization = null,
HttpClient? httpClient = null,
ILogger? logger = null)
ILogger? logger = null) : base(logger)
{
Verify.NotNullOrWhiteSpace(modelId);
Verify.NotNullOrWhiteSpace(apiKey);
@@ -49,4 +50,13 @@ public abstract class OpenAIClientBase : ClientBase
this.Client = new OpenAIClient(apiKey, options);
}
/// <summary>
/// Logs OpenAI action details.
/// </summary>
/// <param name="callerMemberName">Caller member name. Populated automatically by runtime.</param>
private protected void LogActionDetails([CallerMemberName] string? callerMemberName = default)
{
this.Logger.LogInformation("Action: {Action}. OpenAI Model ID: {ModelId}.", callerMemberName, this.ModelId);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/AzureChatCompletion.cs
+4
View File
@@ -72,6 +72,7 @@ public sealed class AzureChatCompletion : AzureOpenAIClientBase, IChatCompletion
ChatRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatResultsAsync(chat, requestSettings, cancellationToken);
}
@@ -81,6 +82,7 @@ public sealed class AzureChatCompletion : AzureOpenAIClientBase, IChatCompletion
ChatRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatStreamingResultsAsync(chat, requestSettings, cancellationToken);
}
@@ -96,6 +98,7 @@ public sealed class AzureChatCompletion : AzureOpenAIClientBase, IChatCompletion
CompleteRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatStreamingResultsAsTextAsync(text, requestSettings, cancellationToken);
}
@@ -105,6 +108,7 @@ public sealed class AzureChatCompletion : AzureOpenAIClientBase, IChatCompletion
CompleteRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatResultsAsTextAsync(text, requestSettings, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/OpenAIChatCompletion.cs
+4
View File
@@ -41,6 +41,7 @@ public sealed class OpenAIChatCompletion : OpenAIClientBase, IChatCompletion, IT
ChatRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatResultsAsync(chat, requestSettings, cancellationToken);
}
@@ -50,6 +51,7 @@ public sealed class OpenAIChatCompletion : OpenAIClientBase, IChatCompletion, IT
ChatRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatStreamingResultsAsync(chat, requestSettings, cancellationToken);
}
@@ -65,6 +67,7 @@ public sealed class OpenAIChatCompletion : OpenAIClientBase, IChatCompletion, IT
CompleteRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatStreamingResultsAsTextAsync(text, requestSettings, cancellationToken);
}
@@ -74,6 +77,7 @@ public sealed class OpenAIChatCompletion : OpenAIClientBase, IChatCompletion, IT
CompleteRequestSettings? requestSettings = null,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetChatResultsAsTextAsync(text, requestSettings, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/CustomClient/OpenAIClientBase.cs
+2 -2
View File
@@ -93,7 +93,7 @@ public abstract class OpenAIClientBase
}
catch (Exception ex) when (ex is NotSupportedException or JsonException)
{
this._log.LogTrace("Unable to extract error from response body content. Exception: {0}:{1}", ex.GetType(), ex.Message);
this._log.LogError(ex, "Unable to extract error from response body content. Exception: {0}:{1}", ex.GetType(), ex.Message);
}
return null;
@@ -159,7 +159,7 @@ public abstract class OpenAIClientBase
response = await this._httpClient.SendAsync(request, cancellationToken).ConfigureAwait(false);
}
this._log.LogTrace("HTTP response: {0} {1}", (int)response.StatusCode, response.StatusCode.ToString("G"));
this._log.LogDebug("HTTP response: {0} {1}", (int)response.StatusCode, response.StatusCode.ToString("G"));
if (response.IsSuccessStatusCode)
{
dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/AzureTextCompletion.cs
+2
View File
@@ -71,6 +71,7 @@ public sealed class AzureTextCompletion : AzureOpenAIClientBase, ITextCompletion
CompleteRequestSettings requestSettings,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetTextStreamingResultsAsync(text, requestSettings, cancellationToken);
}
@@ -80,6 +81,7 @@ public sealed class AzureTextCompletion : AzureOpenAIClientBase, ITextCompletion
CompleteRequestSettings requestSettings,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetTextResultsAsync(text, requestSettings, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/OpenAITextCompletion.cs
+2
View File
@@ -40,6 +40,7 @@ public sealed class OpenAITextCompletion : OpenAIClientBase, ITextCompletion
CompleteRequestSettings requestSettings,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetTextStreamingResultsAsync(text, requestSettings, cancellationToken);
}
@@ -49,6 +50,7 @@ public sealed class OpenAITextCompletion : OpenAIClientBase, ITextCompletion
CompleteRequestSettings requestSettings,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetTextResultsAsync(text, requestSettings, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/AzureTextEmbeddingGeneration.cs
+1
View File
@@ -60,6 +60,7 @@ public sealed class AzureTextEmbeddingGeneration : AzureOpenAIClientBase, ITextE
IList<string> data,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetEmbeddingsAsync(data, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/OpenAITextEmbeddingGeneration.cs
+1
View File
@@ -43,6 +43,7 @@ public sealed class OpenAITextEmbeddingGeneration : OpenAIClientBase, ITextEmbed
IList<string> data,
CancellationToken cancellationToken = default)
{
this.LogActionDetails();
return this.InternalGetEmbeddingsAsync(data, cancellationToken);
}
}
dotnet/src/Connectors/Connectors.Memory.CosmosDB/CosmosMemoryStore.cs
+6 -6
View File
@@ -52,11 +52,11 @@ public sealed class CosmosMemoryStore : IMemoryStore
if (response.StatusCode == HttpStatusCode.Created)
{
newStore._log.LogInformation("Created database {0}", newStore._databaseName);
newStore._log.LogDebug("Created database {0}", newStore._databaseName);
}
else if (response.StatusCode == HttpStatusCode.OK)
{
newStore._log.LogInformation("Database {0}", newStore._databaseName);
newStore._log.LogDebug("Database {0}", newStore._databaseName);
}
else
{
@@ -84,11 +84,11 @@ public sealed class CosmosMemoryStore : IMemoryStore
if (response.StatusCode == HttpStatusCode.Created)
{
this._log.LogInformation("Created collection {0}", collectionName);
this._log.LogDebug("Created collection {0}", collectionName);
}
else if (response.StatusCode == HttpStatusCode.OK)
{
this._log.LogInformation("Collection {0} already exists", collectionName);
this._log.LogDebug("Collection {0} already exists", collectionName);
}
else
{
@@ -191,7 +191,7 @@ public sealed class CosmosMemoryStore : IMemoryStore
if (response.StatusCode is HttpStatusCode.OK or HttpStatusCode.Created)
{
this._log.LogInformation("Upserted item to collection {0}", collectionName);
this._log.LogDebug("Upserted item to collection {0}", collectionName);
}
else
{
@@ -221,7 +221,7 @@ public sealed class CosmosMemoryStore : IMemoryStore
if (response.StatusCode == HttpStatusCode.OK)
{
this._log.LogInformation("Record deleted from {0}", collectionName);
this._log.LogDebug("Record deleted from {0}", collectionName);
}
else
{
dotnet/src/Connectors/Connectors.Memory.Pinecone/PineconeClient.cs
+22 -17
View File
@@ -47,7 +47,7 @@ public sealed class PineconeClient : IPineconeClient
bool includeValues = false,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Searching vectors by id");
this._logger.LogDebug("Searching vectors by id");
string basePath = await this.GetVectorOperationsApiBasePathAsync(indexName).ConfigureAwait(false);
@@ -101,7 +101,7 @@ public sealed class PineconeClient : IPineconeClient
bool includeMetadata = true,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Querying top {0} nearest vectors", query.TopK);
this._logger.LogDebug("Querying top {0} nearest vectors", query.TopK);
using HttpRequestMessage request = QueryRequest.QueryIndex(query)
.WithMetadata(includeMetadata)
@@ -154,7 +154,7 @@ public sealed class PineconeClient : IPineconeClient
Dictionary<string, object>? filter = default,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Searching top {0} nearest vectors with threshold {1}", topK, threshold);
this._logger.LogDebug("Searching top {0} nearest vectors with threshold {1}", topK, threshold);
List<(PineconeDocument document, float score)> documents = new();
@@ -203,7 +203,7 @@ public sealed class PineconeClient : IPineconeClient
string indexNamespace = "",
CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Upserting vectors");
this._logger.LogDebug("Upserting vectors");
int totalUpserted = 0;
int totalBatches = 0;
@@ -239,10 +239,10 @@ public sealed class PineconeClient : IPineconeClient
totalUpserted += data.UpsertedCount;
this._logger.LogInformation("Upserted batch {0} with {1} vectors", totalBatches, data.UpsertedCount);
this._logger.LogDebug("Upserted batch {0} with {1} vectors", totalBatches, data.UpsertedCount);
}
this._logger.LogInformation("Upserted {0} vectors in {1} batches", totalUpserted, totalBatches);
this._logger.LogDebug("Upserted {0} vectors in {1} batches", totalUpserted, totalBatches);
return totalUpserted;
}
@@ -273,7 +273,7 @@ public sealed class PineconeClient : IPineconeClient
.FromNamespace(indexNamespace)
.FilterBy(filter);
this._logger.LogInformation("Delete operation for Index {0}: {1}", indexName, deleteRequest.ToString());
this._logger.LogDebug("Delete operation for Index {0}: {1}", indexName, deleteRequest.ToString());
string basePath = await this.GetVectorOperationsApiBasePathAsync(indexName).ConfigureAwait(false);
@@ -295,7 +295,7 @@ public sealed class PineconeClient : IPineconeClient
/// <inheritdoc />
public async Task UpdateAsync(string indexName, PineconeDocument document, string indexNamespace = "", CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Updating vector: {0}", document.Id);
this._logger.LogDebug("Updating vector: {0}", document.Id);
string basePath = await this.GetVectorOperationsApiBasePathAsync(indexName).ConfigureAwait(false);
@@ -380,7 +380,7 @@ public sealed class PineconeClient : IPineconeClient
/// <inheritdoc />
public async Task CreateIndexAsync(IndexDefinition indexDefinition, CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Creating index {0}", indexDefinition.ToString());
this._logger.LogDebug("Creating index {0}", indexDefinition.ToString());
string indexName = indexDefinition.Name;
@@ -412,7 +412,7 @@ public sealed class PineconeClient : IPineconeClient
/// <inheritdoc />
public async Task DeleteIndexAsync(string indexName, CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Deleting index {0}", indexName);
this._logger.LogDebug("Deleting index {0}", indexName);
using HttpRequestMessage request = DeleteIndexRequest.Create(indexName).Build();
@@ -433,13 +433,13 @@ public sealed class PineconeClient : IPineconeClient
throw;
}
this._logger.LogInformation("Index: {0} has been successfully deleted.", indexName);
this._logger.LogDebug("Index: {0} has been successfully deleted.", indexName);
}
/// <inheritdoc />
public async Task<bool> DoesIndexExistAsync(string indexName, CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Checking for index {0}", indexName);
this._logger.LogDebug("Checking for index {0}", indexName);
List<string?>? indexNames = await this.ListIndexesAsync(cancellationToken).ToListAsync(cancellationToken).ConfigureAwait(false);
@@ -558,9 +558,14 @@ public sealed class PineconeClient : IPineconeClient
string responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
string logMessage = response.IsSuccessStatusCode ? "Pinecone responded successfully" : "Pinecone responded with error";
this._logger.LogTrace("{0} - {1}", logMessage, responseContent);
if (response.IsSuccessStatusCode)
{
this._logger.LogDebug("Pinecone responded successfully");
}
else
{
this._logger.LogWarning("Pinecone responded with error");
}
return (response, responseContent);
}
@@ -572,7 +577,7 @@ public sealed class PineconeClient : IPineconeClient
return indexHost;
}
this._logger.LogInformation("Getting index host from Pinecone.");
this._logger.LogDebug("Getting index host from Pinecone.");
PineconeIndex? pineconeIndex = await this.DescribeIndexAsync(indexName, cancellationToken).ConfigureAwait(false);
@@ -590,7 +595,7 @@ public sealed class PineconeClient : IPineconeClient
$"Host of index {indexName} is unknown.");
}
this._logger.LogInformation("Found host {0} for index {1}", pineconeIndex.Status.Host, indexName);
this._logger.LogDebug("Found host {0} for index {1}", pineconeIndex.Status.Host, indexName);
this._indexHostMapping.TryAdd(indexName, pineconeIndex.Status.Host);
dotnet/src/Connectors/Connectors.Memory.Qdrant/QdrantVectorDbClient.cs
+3 -2
View File
@@ -459,13 +459,14 @@ public sealed class QdrantVectorDbClient : IQdrantVectorDbClient
HttpResponseMessage response = await this._httpClient.SendAsync(request, cancellationToken).ConfigureAwait(false);
string responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
if (response.IsSuccessStatusCode)
{
this._logger.LogTrace("Qdrant responded successfully");
this._logger.LogDebug("Qdrant responded successfully");
}
else
{
this._logger.LogTrace("Qdrant responded with error");
this._logger.LogWarning("Qdrant responded with error");
}
return (response, responseContent);
dotnet/src/Connectors/Connectors.Memory.Weaviate/WeaviateMemoryStore.cs
+20 -12
View File
@@ -104,7 +104,7 @@ public class WeaviateMemoryStore : IMemoryStore
string className = ToWeaviateFriendlyClassName(collectionName);
string description = ToWeaviateFriendlyClassDescription(collectionName);
this._logger.LogTrace("Creating collection: {0}, with class name: {1}", collectionName, className);
this._logger.LogDebug("Creating collection: {0}, with class name: {1}", collectionName, className);
using HttpRequestMessage request = CreateClassSchemaRequest.Create(className, description).Build();
@@ -120,7 +120,7 @@ public class WeaviateMemoryStore : IMemoryStore
$"Name conflict for collection: {collectionName} with class name: {className}");
}
this._logger.LogTrace("Created collection: {0}, with class name: {1}", collectionName, className);
this._logger.LogDebug("Created collection: {0}, with class name: {1}", collectionName, className);
}
catch (HttpRequestException e)
{
@@ -135,7 +135,8 @@ public class WeaviateMemoryStore : IMemoryStore
Verify.NotNullOrWhiteSpace(collectionName, "Collection name is empty");
string className = ToWeaviateFriendlyClassName(collectionName);
this._logger.LogTrace("Does collection exist: {0}, with class name: {1}:", collectionName, className);
this._logger.LogDebug("Does collection exist: {0}, with class name: {1}:", collectionName, className);
using HttpRequestMessage request = GetClassRequest.Create(className).Build();
@@ -147,7 +148,7 @@ public class WeaviateMemoryStore : IMemoryStore
bool exists = response.StatusCode != HttpStatusCode.NotFound;
if (!exists)
{
this._logger.LogTrace("Collection: {0}, with class name: {1}, does not exist.", collectionName, className);
this._logger.LogDebug("Collection: {0}, with class name: {1}, does not exist.", collectionName, className);
}
else
{
@@ -174,7 +175,7 @@ public class WeaviateMemoryStore : IMemoryStore
/// <inheritdoc />
public async IAsyncEnumerable<string> GetCollectionsAsync([EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this._logger.LogTrace("Listing collections");
this._logger.LogDebug("Listing collections");
using HttpRequestMessage request = GetSchemaRequest.Create().Build();
string responseContent;
@@ -206,7 +207,8 @@ public class WeaviateMemoryStore : IMemoryStore
Verify.NotNullOrWhiteSpace(collectionName, "Collection name is empty");
string className = ToWeaviateFriendlyClassName(collectionName);
this._logger.LogTrace("Deleting collection: {0}, with class name: {1}", collectionName, className);
this._logger.LogDebug("Deleting collection: {0}, with class name: {1}", collectionName, className);
if (await this.DoesCollectionExistAsync(collectionName, cancellationToken).ConfigureAwait(false))
{
@@ -237,7 +239,7 @@ public class WeaviateMemoryStore : IMemoryStore
{
Verify.NotNullOrWhiteSpace(collectionName, "Collection name is empty");
this._logger.LogTrace("Upsert vectors");
this._logger.LogDebug("Upsert vectors");
string className = ToWeaviateFriendlyClassName(collectionName);
BatchRequest requestBuilder = BatchRequest.Create(className);
@@ -315,7 +317,7 @@ public class WeaviateMemoryStore : IMemoryStore
embedding: new(weaviateObject.Vector ?? Array.Empty<float>()),
metadata: ToMetadata(weaviateObject));
this._logger.LogTrace("Vector found with key: {0}", key);
this._logger.LogDebug("Vector found with key: {0}", key);
return record;
}
@@ -345,7 +347,8 @@ public class WeaviateMemoryStore : IMemoryStore
Verify.NotNull(key, "Key is NULL");
string className = ToWeaviateFriendlyClassName(collectionName);
this._logger.LogTrace("Deleting vector with key: {0}, from collection {1}, with class name: {2}:", key, collectionName, className);
this._logger.LogDebug("Deleting vector with key: {0}, from collection {1}, with class name: {2}:", key, collectionName, className);
DeleteObjectRequest requestBuilder = new()
{
@@ -359,7 +362,8 @@ public class WeaviateMemoryStore : IMemoryStore
{
(HttpResponseMessage response, string _) = await this.ExecuteHttpRequestAsync(request, cancellationToken).ConfigureAwait(false);
response.EnsureSuccessStatusCode();
this._logger.LogTrace("Vector deleted");
this._logger.LogDebug("Vector deleted");
}
catch (HttpRequestException e)
{
@@ -382,8 +386,10 @@ public class WeaviateMemoryStore : IMemoryStore
bool withEmbeddings = false,
[EnumeratorCancellation] CancellationToken cancellationToken = default)
{
this._logger.LogTrace("Searching top {0} nearest vectors", limit);
Verify.NotNull(embedding, "The given vector is NULL");
this._logger.LogDebug("Searching top {0} nearest vectors", limit);
string className = ToWeaviateFriendlyClassName(collectionName);
using HttpRequestMessage request = new CreateGraphRequest
@@ -517,7 +523,9 @@ public class WeaviateMemoryStore : IMemoryStore
HttpResponseMessage response = await this._httpClient.SendAsync(request, cancel).ConfigureAwait(false);
string? responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
this._logger.LogTrace("Weaviate responded with {0}", response.StatusCode);
this._logger.LogDebug("Weaviate responded with {0}", response.StatusCode);
return (response, responseContent);
}
dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs
+19
View File
@@ -0,0 +1,19 @@
// Copyright (c) Microsoft. All rights reserved.
using System.Threading.Tasks;
namespace Microsoft.SemanticKernel.Planning.Sequential;
/// <summary>
/// Interface for planner that uses semantic function to create a sequential plan.
/// </summary>
public interface ISequentialPlanner
{
/// <summary>
/// Create a plan for a goal.
/// </summary>
/// <param name="goal">The goal to create a plan for.</param>
/// <returns>The plan.</returns>
/// <exception cref="PlanningException">Thrown when the plan cannot be created.</exception>
Task<Plan> CreatePlanAsync(string goal);
}
dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs
+100
View File
@@ -0,0 +1,100 @@
// Copyright (c) Microsoft. All rights reserved.
using System;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
namespace Microsoft.SemanticKernel.Planning.Sequential;
/// <summary>
/// Instrumented planner that uses semantic function to create a sequential plan.
/// Captures planner-related logs and metrics.
/// </summary>
public sealed class InstrumentedSequentialPlanner : ISequentialPlanner
{
/// <summary>
/// Initialize a new instance of the <see cref="InstrumentedSequentialPlanner"/> class.
/// </summary>
/// <param name="planner">Instance of <see cref="ISequentialPlanner"/> to decorate.</param>
/// <param name="logger">Optional logger.</param>
public InstrumentedSequentialPlanner(
ISequentialPlanner planner,
ILogger? logger = null)
{
this._planner = planner;
this._logger = logger ?? NullLogger.Instance;
}
/// <inheritdoc />
public async Task<Plan> CreatePlanAsync(string goal)
{
using var activity = s_activitySource.StartActivity("SequentialPlanner.CreatePlan");
this._logger.LogInformation("Plan creation started.");
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Plan Goal: {Goal}", goal);
var stopwatch = new Stopwatch();
try
{
stopwatch.Start();
var plan = await this._planner.CreatePlanAsync(goal).ConfigureAwait(false);
stopwatch.Stop();
this._logger.LogInformation("Plan creation status: {Status}", "Success");
this._logger.LogInformation("Created plan: \n {Plan}", plan.ToSafePlanString());
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Created plan with details: \n {Plan}", plan.ToPlanString());
return plan;
}
catch (Exception ex)
{
this._logger.LogInformation("Plan creation status: {Status}", "Failed");
this._logger.LogError(ex, "Plan creation exception details: {Message}", ex.Message);
throw;
}
finally
{
this._logger.LogInformation("Plan creation finished in {ExecutionTime}ms.", stopwatch.ElapsedMilliseconds);
s_createPlanExecutionTime.Record(stopwatch.ElapsedMilliseconds);
}
}
#region private ================================================================================
private readonly ISequentialPlanner _planner;
private readonly ILogger _logger;
/// <summary>
/// Instance of <see cref="ActivitySource"/> for planner-related activities.
/// </summary>
private static ActivitySource s_activitySource = new(typeof(InstrumentedSequentialPlanner).FullName);
/// <summary>
/// Instance of <see cref="Meter"/> for planner-related metrics.
/// </summary>
private static Meter s_meter = new(typeof(InstrumentedSequentialPlanner).FullName);
/// <summary>
/// Instance of <see cref="Histogram{T}"/> to record plan creation execution time.
/// </summary>
private static Histogram<double> s_createPlanExecutionTime =
s_meter.CreateHistogram<double>(
name: "SK.SequentialPlanner.CreatePlan.ExecutionTime",
unit: "ms",
description: "Execution time of plan creation");
#endregion
}
dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlanner.cs
+2 -7
View File
@@ -15,7 +15,7 @@ namespace Microsoft.SemanticKernel.Planning;
/// <summary>
/// A planner that uses semantic function to create a sequential plan.
/// </summary>
public sealed class SequentialPlanner
public sealed class SequentialPlanner : ISequentialPlanner
{
private const string StopSequence = "<!-- END -->";
@@ -49,12 +49,7 @@ public sealed class SequentialPlanner
this._context = kernel.CreateNewContext();
}
/// <summary>
/// Create a plan for a goal.
/// </summary>
/// <param name="goal">The goal to create a plan for.</param>
/// <returns>The plan.</returns>
/// <exception cref="PlanningException">Thrown when the plan cannot be created.</exception>
/// <inheritdoc />
public async Task<Plan> CreatePlanAsync(string goal)
{
if (string.IsNullOrEmpty(goal))
dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlannerExtensions.cs
+21
View File
@@ -0,0 +1,21 @@
// Copyright (c) Microsoft. All rights reserved.
using Microsoft.Extensions.Logging;
namespace Microsoft.SemanticKernel.Planning.Sequential;
/// <summary>
/// Extension methods for <see cref="SequentialPlanner"/> class.
/// </summary>
public static class SequentialPlannerExtensions
{
/// <summary>
/// Returns decorated instance of <see cref="ISequentialPlanner"/> with enabled instrumentation.
/// </summary>
/// <param name="planner">Instance of <see cref="ISequentialPlanner"/> to decorate.</param>
/// <param name="logger">Optional logger.</param>
public static ISequentialPlanner WithInstrumentation(this ISequentialPlanner planner, ILogger? logger = null)
{
return new InstrumentedSequentialPlanner(planner, logger);
}
}
dotnet/src/IntegrationTests/Fakes/EmailSkillFake.cs
+2 -2
View File
@@ -25,11 +25,11 @@ internal sealed class EmailSkillFake
{
if (string.IsNullOrEmpty(input))
{
logger.LogDebug("Returning hard coded email for {0}", input);
logger.LogTrace("Returning hard coded email for {0}", input);
return Task.FromResult("[email protected]");
}
logger.LogDebug("Returning dynamic email for {0}", input);
logger.LogTrace("Returning dynamic email for {0}", input);
return Task.FromResult($"{input}@example.com");
}
dotnet/src/SemanticKernel.Abstractions/Diagnostics/ITelemetryService.cs
-17
View File
@@ -1,17 +0,0 @@
// Copyright (c) Microsoft. All rights reserved.
namespace Microsoft.SemanticKernel.Diagnostics;
/// <summary>
/// Interface for common telemetry events to track actions across the semantic kernel.
/// </summary>
public interface ITelemetryService
{
/// <summary>
/// Creates a telemetry event when a skill function is executed.
/// </summary>
/// <param name="skillName">Name of the skill</param>
/// <param name="functionName">Skill function name</param>
/// <param name="success">If the skill executed successfully</param>
void TrackSkillFunction(string skillName, string functionName, bool success);
}
dotnet/src/SemanticKernel/Planning/Plan.cs
+78 -5
View File
@@ -3,6 +3,8 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using System.Globalization;
using System.Linq;
using System.Text.Json;
using System.Text.Json.Serialization;
@@ -231,6 +233,7 @@ public sealed class Plan : ISKFunction
kernel.Skills,
kernel.Log,
cancellationToken);
return this.InvokeNextStepAsync(context);
}
@@ -250,7 +253,13 @@ public sealed class Plan : ISKFunction
var functionVariables = this.GetNextStepVariables(context.Variables, step);
// Execute the step
var functionContext = new SKContext(functionVariables, context.Memory, context.Skills, context.Log, context.CancellationToken);
var functionContext = new SKContext(
functionVariables,
context.Memory,
context.Skills,
context.Log,
context.CancellationToken);
var result = await step.InvokeAsync(functionContext).ConfigureAwait(false);
var resultValue = result.Result.Trim();
@@ -328,13 +337,10 @@ public sealed class Plan : ISKFunction
{
if (this.Function is not null)
{
var result = await this.Function.InvokeAsync(context, settings).ConfigureAwait(false);
var result = await this.InstrumentedInvokeAsync(this.Function, context, settings).ConfigureAwait(false);
if (result.ErrorOccurred)
{
result.Log.LogError(
result.LastException,
"Something went wrong in plan step {0}.{1}:'{2}'", this.SkillName, this.Name, context.LastErrorDescription);
return result;
}
@@ -587,6 +593,57 @@ public sealed class Plan : ISKFunction
return stepVariables;
}
private async Task<SKContext> InstrumentedInvokeAsync(
ISKFunction function,
SKContext context,
CompleteRequestSettings? settings = null)
{
using var activity = s_activitySource.StartActivity($"{this.SkillName}.{this.Name}");
context.Log.LogInformation("{SkillName}.{StepName}: Step execution started.", this.SkillName, this.Name);
var stopwatch = new Stopwatch();
stopwatch.Start();
var result = await function.InvokeAsync(context, settings).ConfigureAwait(false);
stopwatch.Stop();
if (!result.ErrorOccurred)
{
context.Log.LogInformation(
"{SkillName}.{StepName}: Step execution status: {Status}.",
this.SkillName, this.Name, "Success");
}
else
{
context.Log.LogInformation(
"{SkillName}.{StepName}: Step execution status: {Status}.",
this.SkillName, this.Name, "Failed");
context.Log.LogError(
result.LastException,
"Something went wrong in plan step {SkillName}.{StepName}:'{ErrorDescription}'",
this.SkillName, this.Name, context.LastErrorDescription);
}
context.Log.LogInformation(
"{SkillName}.{StepName}: Step execution finished in {ExecutionTime}ms.",
this.SkillName, this.Name, stopwatch.ElapsedMilliseconds);
var stepExecutionTimeMetricName = string.Format(CultureInfo.InvariantCulture, StepExecutionTimeMetricFormat, this.SkillName, this.Name);
var stepExecutionTimeHistogram = s_meter.CreateHistogram<double>(
name: stepExecutionTimeMetricName,
unit: "ms",
description: "Plan step execution time");
stepExecutionTimeHistogram.Record(stopwatch.ElapsedMilliseconds);
return result;
}
private void SetFunction(ISKFunction function)
{
this.Function = function;
@@ -625,4 +682,20 @@ public sealed class Plan : ISKFunction
return display;
}
}
#region Instrumentation
private const string StepExecutionTimeMetricFormat = "SK.{0}.{1}.ExecutionTime";
/// <summary>
/// Instance of <see cref="ActivitySource"/> for plan-related activities.
/// </summary>
private static ActivitySource s_activitySource = new(typeof(Plan).FullName);
/// <summary>
/// Instance of <see cref="Meter"/> for planner-related metrics.
/// </summary>
private static Meter s_meter = new(typeof(Plan).FullName);
#endregion
}
dotnet/src/SemanticKernel/Planning/PlanExtensions.cs
+69
View File
@@ -0,0 +1,69 @@
// Copyright (c) Microsoft. All rights reserved.
using System.Linq;
namespace Microsoft.SemanticKernel.Planning;
/// <summary>
/// Extension methods for <see cref="Plan"/> type.
/// </summary>
public static class PlanExtensions
{
/// <summary>
/// Constructs string representation of <see cref="Plan"/> without sensitive data.
/// </summary>
/// <param name="plan">Instance of <see cref="Plan"/> for string construction.</param>
/// <param name="indent">Optional indentation.</param>
public static string ToSafePlanString(this Plan plan, string indent = " ")
{
string planString = string.Join("\n", plan.Steps.Select(step =>
{
if (step.Steps.Count == 0)
{
string skillName = step.SkillName;
string stepName = step.Name;
return $"{indent}{indent}- {string.Join(".", skillName, stepName)}";
}
return step.ToSafePlanString(indent + indent);
}));
return planString;
}
/// <summary>
/// Constructs string representation of <see cref="Plan"/>.
/// </summary>
/// <param name="plan">Instance of <see cref="Plan"/> for string construction.</param>
/// <param name="indent">Optional indentation.</param>
public static string ToPlanString(this Plan plan, string indent = " ")
{
string planString = string.Join("\n", plan.Steps.Select(step =>
{
if (step.Steps.Count == 0)
{
string skillName = step.SkillName;
string stepName = step.Name;
string parameters = string.Join(" ", step.Parameters.Select(param => $"{param.Key}='{param.Value}'"));
if (!string.IsNullOrEmpty(parameters))
{
parameters = $" {parameters}";
}
string? outputs = step.Outputs.FirstOrDefault();
if (!string.IsNullOrEmpty(outputs))
{
outputs = $" => {outputs}";
}
return $"{indent}{indent}- {string.Join(".", skillName, stepName)}{parameters}{outputs}";
}
return step.ToPlanString(indent + indent);
}));
return planString;
}
}
dotnet/src/SemanticKernel/SemanticKernel.csproj
+4
View File
@@ -25,6 +25,10 @@
<InternalsVisibleTo Include="SemanticKernel.UnitTests" />
</ItemGroup>
<ItemGroup>
<PackageReference Include="System.Diagnostics.DiagnosticSource" />
</ItemGroup>
<ItemGroup>
<ProjectReference Include="..\SemanticKernel.Abstractions\SemanticKernel.Abstractions.csproj" />
</ItemGroup>
dotnet/src/SemanticKernel/TemplateEngine/Blocks/CodeBlock.cs
+2 -1
View File
@@ -119,8 +119,9 @@ internal sealed class CodeBlock : Block, ICodeRendering
// If the code syntax is {{functionName 'value'}} use "value" instead of $input
if (this._tokens.Count > 1)
{
// TODO: PII
// Sensitive data, logging as trace, disabled by default
this.Log.LogTrace("Passing variable/value: `{0}`", this._tokens[1].Content);
string input = ((ITextRendering)this._tokens[1]).Render(contextClone.Variables);
// Keep previous trust information when updating the input
contextClone.Variables.Update(input);
dotnet/src/SemanticKernel/TemplateEngine/PromptTemplateEngine.cs
+3 -2
View File
@@ -91,8 +91,9 @@ public class PromptTemplateEngine : IPromptTemplateEngine
result.Append(await t.ConfigureAwait(false));
}
// TODO: remove PII, allow tracing prompts differently
this._log.LogDebug("Rendered prompt: {0}", result);
// Sensitive data, logging as trace, disabled by default
this._log.LogTrace("Rendered prompt: {0}", result);
return result.ToString();
}
dotnet/src/Skills/Skills.Core/TextMemorySkill.cs
+5 -5
View File
@@ -74,7 +74,7 @@ public sealed class TextMemorySkill
Verify.NotNullOrWhiteSpace(collection, $"{nameof(context)}.{nameof(context.Variables)}[{CollectionParam}]");
Verify.NotNullOrWhiteSpace(key, $"{nameof(context)}.{nameof(context.Variables)}[{KeyParam}]");
context.Log.LogTrace("Recalling memory with key '{0}' from collection '{1}'", key, collection);
context.Log.LogDebug("Recalling memory with key '{0}' from collection '{1}'", key, collection);
var memory = await context.Memory.GetAsync(collection, key).ConfigureAwait(false);
@@ -105,7 +105,7 @@ public sealed class TextMemorySkill
relevance ??= DefaultRelevance;
limit ??= DefaultLimit;
context.Log.LogTrace("Searching memories in collection '{0}', relevance '{1}'", collection, relevance);
context.Log.LogDebug("Searching memories in collection '{0}', relevance '{1}'", collection, relevance);
// Search memory
List<MemoryQueryResult> memories = await context.Memory
@@ -119,7 +119,7 @@ public sealed class TextMemorySkill
return string.Empty;
}
context.Log.LogTrace("Done looking for memories in collection '{0}')", collection);
context.Log.LogDebug("Done looking for memories in collection '{0}')", collection);
return limit == 1 ? memories[0].Metadata.Text : JsonSerializer.Serialize(memories.Select(x => x.Metadata.Text));
}
@@ -145,7 +145,7 @@ public sealed class TextMemorySkill
Verify.NotNullOrWhiteSpace(collection, $"{nameof(context)}.{nameof(context.Variables)}[{CollectionParam}]");
Verify.NotNullOrWhiteSpace(key, $"{nameof(context)}.{nameof(context.Variables)}[{KeyParam}]");
context.Log.LogTrace("Saving memory to collection '{0}'", collection);
context.Log.LogDebug("Saving memory to collection '{0}'", collection);
await context.Memory.SaveInformationAsync(collection, text: text, id: key).ConfigureAwait(false);
}
@@ -169,7 +169,7 @@ public sealed class TextMemorySkill
Verify.NotNullOrWhiteSpace(collection, $"{nameof(context)}.{nameof(context.Variables)}[{CollectionParam}]");
Verify.NotNullOrWhiteSpace(key, $"{nameof(context)}.{nameof(context.Variables)}[{KeyParam}]");
context.Log.LogTrace("Removing memory from collection '{0}'", collection);
context.Log.LogDebug("Removing memory from collection '{0}'", collection);
await context.Memory.RemoveAsync(collection, key).ConfigureAwait(false);
}
dotnet/src/Skills/Skills.Document/DocumentSkill.cs
+4 -4
View File
@@ -75,7 +75,7 @@ public sealed class DocumentSkill
[Description("Path to the file to read")] string filePath,
CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Reading text from {0}", filePath);
this._logger.LogDebug("Reading text from {0}", filePath);
using var stream = await this._fileSystemConnector.GetFileContentStreamAsync(filePath, cancellationToken).ConfigureAwait(false);
return this._documentConnector.ReadText(stream);
}
@@ -97,17 +97,17 @@ public sealed class DocumentSkill
// If the document already exists, open it. If not, create it.
if (await this._fileSystemConnector.FileExistsAsync(filePath, cancellationToken).ConfigureAwait(false))
{
this._logger.LogInformation("Writing text to file {0}", filePath);
this._logger.LogDebug("Writing text to file {0}", filePath);
using Stream stream = await this._fileSystemConnector.GetWriteableFileStreamAsync(filePath, cancellationToken).ConfigureAwait(false);
this._documentConnector.AppendText(stream, text);
}
else
{
this._logger.LogInformation("File does not exist. Creating file at {0}", filePath);
this._logger.LogDebug("File does not exist. Creating file at {0}", filePath);
using Stream stream = await this._fileSystemConnector.CreateFileAsync(filePath, cancellationToken).ConfigureAwait(false);
this._documentConnector.Initialize(stream);
this._logger.LogInformation("Writing text to {0}", filePath);
this._logger.LogDebug("Writing text to {0}", filePath);
this._documentConnector.AppendText(stream, text);
}
}
dotnet/src/Skills/Skills.MsGraph/CalendarSkill.cs
+3 -2
View File
@@ -111,7 +111,8 @@ public sealed class CalendarSkill
Attendees = attendees is not null ? attendees.Split(new[] { ',', ';' }, StringSplitOptions.RemoveEmptyEntries) : Enumerable.Empty<string>(),
};
this._logger.LogInformation("Adding calendar event '{0}'", calendarEvent.Subject);
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Adding calendar event '{0}'", calendarEvent.Subject);
await this._connector.AddEventAsync(calendarEvent).ConfigureAwait(false);
}
@@ -124,7 +125,7 @@ public sealed class CalendarSkill
[Description("Optional number of events to skip before retrieving results.")] int? skip = 0,
CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Getting calendar events with query options top: '{0}', skip:'{1}'.", maxResults, skip);
this._logger.LogDebug("Getting calendar events with query options top: '{0}', skip:'{1}'.", maxResults, skip);
const string SelectString = "start,subject,organizer,location";
dotnet/src/Skills/Skills.MsGraph/CloudDriveSkill.cs
+1 -1
View File
@@ -53,7 +53,7 @@ public sealed class CloudDriveSkill
using StreamReader sr = new(fileContentStream);
string content = await sr.ReadToEndAsync().ConfigureAwait(false);
this._logger.LogDebug("File content: {0}", content);
return content;
}
dotnet/src/Skills/Skills.MsGraph/EmailSkill.cs
+3 -2
View File
@@ -95,7 +95,8 @@ public sealed class EmailSkill
throw new ArgumentException("Variable was null or whitespace", nameof(subject));
}
this._logger.LogInformation("Sending email to '{0}' with subject '{1}'", recipients, subject);
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Sending email to '{0}' with subject '{1}'", recipients, subject);
string[] recipientList = recipients.Split(new[] { ',', ';' }, StringSplitOptions.RemoveEmptyEntries);
await this._connector.SendEmailAsync(subject, content, recipientList, cancellationToken).ConfigureAwait(false);
}
@@ -109,7 +110,7 @@ public sealed class EmailSkill
[Description("Optional number of message to skip before retrieving results.")] int? skip = 0,
CancellationToken cancellationToken = default)
{
this._logger.LogInformation("Getting email messages with query options top: '{0}', skip:'{1}'.", maxResults, skip);
this._logger.LogDebug("Getting email messages with query options top: '{0}', skip:'{1}'.", maxResults, skip);
const string SelectString = "subject,receivedDateTime,bodyPreview";
dotnet/src/Skills/Skills.MsGraph/TaskListSkill.cs
+3 -1
View File
@@ -90,7 +90,9 @@ public sealed class TaskListSkill
title: title,
reminder: reminder);
this._logger.LogInformation("Adding task '{0}' to task list '{1}'", task.Title, defaultTaskList.Name);
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Adding task '{0}' to task list '{1}'", task.Title, defaultTaskList.Name);
await this._connector.AddTaskAsync(defaultTaskList.Id, task, cancellationToken).ConfigureAwait(false);
}
dotnet/src/Skills/Skills.OpenAPI/Extensions/KernelOpenApiExtensions.cs
+1 -1
View File
@@ -335,7 +335,7 @@ public static class KernelOpenApiExtensions
result += CultureInfo.CurrentCulture.TextInfo.ToTitleCase(formattedToken.ToLower(CultureInfo.CurrentCulture));
}
logger.LogInformation("Operation name \"{0}\" converted to \"{1}\" to comply with SK Function name requirements. Use \"{2}\" when invoking function.", operationId, result, result);
logger.LogDebug("Operation name \"{0}\" converted to \"{1}\" to comply with SK Function name requirements. Use \"{2}\" when invoking function.", operationId, result, result);
return result;
}
dotnet/src/Skills/Skills.Web/Bing/BingConnector.cs
+2
View File
@@ -69,6 +69,8 @@ public sealed class BingConnector : IWebSearchEngineConnector
this._logger.LogDebug("Response received: {0}", response.StatusCode);
string json = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
// Sensitive data, logging as trace, disabled by default
this._logger.LogTrace("Response content received: {0}", json);
BingSearchResponse? data = JsonSerializer.Deserialize<BingSearchResponse>(json);
samples/dotnet/openapi-skills/Program.cs
+2 -2
View File
@@ -213,11 +213,11 @@ internal sealed class Program
}
catch (JsonException)
{
logger.LogDebug("Unable to extract JSON from planner response, it is likely not from an OpenAPI skill.");
logger.LogWarning("Unable to extract JSON from planner response, it is likely not from an OpenAPI skill.");
}
catch (InvalidOperationException)
{
logger.LogDebug("Unable to extract JSON from planner response, it may already be proper JSON.");
logger.LogWarning("Unable to extract JSON from planner response, it may already be proper JSON.");
}
json = string.Empty;