From 55dc7942e5aa54e55222927f42a792cc09b7c3c2 Mon Sep 17 00:00:00 2001 From: Dmytro Struk <13853051+dmytrostruk@users.noreply.github.com> Date: Tue, 18 Jul 2023 21:36:37 +0100 Subject: [PATCH] .Net: SK Telemetry improvements (#1905) ### Motivation and Context 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 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 - [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 :smile: --------- Co-authored-by: Shawn Callegari <36091529+shawncal@users.noreply.github.com> --- dotnet/Directory.Packages.props | 2 + dotnet/SK-dotnet.sln | 9 + .../ApplicationInsightsExample.csproj | 27 +++ .../ApplicationInsightsExample/Program.cs | 192 ++++++++++++++++++ .../RepoUtils/Env.cs | 36 ++++ .../RepoUtils/RepoFiles.cs | 39 ++++ .../Example12_SequentialPlanner.cs | 8 +- .../Example31_CustomPlanner.cs | 2 +- .../Example48_GroundednessChecks.cs | 2 +- .../RepoUtils/PlanExtensions.cs | 32 +-- .../KernelSyntaxExamples/Skills/EmailSkill.cs | 4 +- .../AzureSdk/AzureOpenAIClientBase.cs | 14 +- .../AzureSdk/ClientBase.cs | 12 +- .../AzureSdk/OpenAIClientBase.cs | 12 +- .../ChatCompletion/AzureChatCompletion.cs | 4 + .../ChatCompletion/OpenAIChatCompletion.cs | 4 + .../CustomClient/OpenAIClientBase.cs | 4 +- .../TextCompletion/AzureTextCompletion.cs | 2 + .../TextCompletion/OpenAITextCompletion.cs | 2 + .../AzureTextEmbeddingGeneration.cs | 1 + .../OpenAITextEmbeddingGeneration.cs | 1 + .../CosmosMemoryStore.cs | 12 +- .../PineconeClient.cs | 39 ++-- .../QdrantVectorDbClient.cs | 5 +- .../WeaviateMemoryStore.cs | 32 +-- .../ISequentialPlanner.cs | 19 ++ .../InstrumentedSequentialPlanner.cs | 100 +++++++++ .../SequentialPlanner.cs | 9 +- .../SequentialPlannerExtensions.cs | 21 ++ .../IntegrationTests/Fakes/EmailSkillFake.cs | 4 +- .../Diagnostics/ITelemetryService.cs | 17 -- dotnet/src/SemanticKernel/Planning/Plan.cs | 83 +++++++- .../SemanticKernel/Planning/PlanExtensions.cs | 69 +++++++ .../src/SemanticKernel/SemanticKernel.csproj | 4 + .../TemplateEngine/Blocks/CodeBlock.cs | 3 +- .../TemplateEngine/PromptTemplateEngine.cs | 5 +- .../src/Skills/Skills.Core/TextMemorySkill.cs | 10 +- .../Skills/Skills.Document/DocumentSkill.cs | 8 +- .../Skills/Skills.MsGraph/CalendarSkill.cs | 5 +- .../Skills/Skills.MsGraph/CloudDriveSkill.cs | 2 +- .../src/Skills/Skills.MsGraph/EmailSkill.cs | 5 +- .../Skills/Skills.MsGraph/TaskListSkill.cs | 4 +- .../Extensions/KernelOpenApiExtensions.cs | 2 +- .../Skills/Skills.Web/Bing/BingConnector.cs | 2 + samples/dotnet/openapi-skills/Program.cs | 4 +- 45 files changed, 742 insertions(+), 131 deletions(-) create mode 100644 dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj create mode 100644 dotnet/samples/ApplicationInsightsExample/Program.cs create mode 100644 dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs create mode 100644 dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs create mode 100644 dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs create mode 100644 dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs create mode 100644 dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlannerExtensions.cs delete mode 100644 dotnet/src/SemanticKernel.Abstractions/Diagnostics/ITelemetryService.cs create mode 100644 dotnet/src/SemanticKernel/Planning/PlanExtensions.cs diff --git a/dotnet/Directory.Packages.props b/dotnet/Directory.Packages.props index f45e3291ae70..87ba2e1f7a8d 100644 --- a/dotnet/Directory.Packages.props +++ b/dotnet/Directory.Packages.props @@ -8,12 +8,14 @@ + + diff --git a/dotnet/SK-dotnet.sln b/dotnet/SK-dotnet.sln index 7207d47c875a..4b8444a509aa 100644 --- a/dotnet/SK-dotnet.sln +++ b/dotnet/SK-dotnet.sln @@ -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} diff --git a/dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj b/dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj new file mode 100644 index 000000000000..13720b96d9a2 --- /dev/null +++ b/dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj @@ -0,0 +1,27 @@ + + + + net6.0 + LatestMajor + Exe + 10 + enable + disable + false + + CA1050;CA1707;CA2007;VSTHRD111 + 5ee045b0-aea3-4f08-8d31-32d1a6f8fed0 + + + + + + + + + + + + + + diff --git a/dotnet/samples/ApplicationInsightsExample/Program.cs b/dotnet/samples/ApplicationInsightsExample/Program.cs new file mode 100644 index 000000000000..112800797fbb --- /dev/null +++ b/dotnet/samples/ApplicationInsightsExample/Program.cs @@ -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; + +/// +/// Example of telemetry in Semantic Kernel using Application Insights within console application. +/// +public sealed class Program +{ + /// + /// Log level to be used by . + /// + /// + /// is set by default. + /// will enable logging with more detailed information, including sensitive data. Should not be used in production. + /// + private static LogLevel LogLevel = LogLevel.Information; + + public static async Task Main() + { + var serviceProvider = GetServiceProvider(); + + var telemetryClient = serviceProvider.GetRequiredService(); + var logger = serviceProvider.GetRequiredService>(); + + 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("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(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); + } + + /// + /// Example of metering configuration in Application Insights + /// using to attach for recordings. + /// + /// Instance of for metering configuration. + /// Instance of Application Insights . + 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 measurementCallback = (instrument, measurement, tags, state) => + { + telemetryClient.GetMetric(instrument.Name).TrackValue(measurement); + }; + + meterListener.SetMeasurementEventCallback(measurementCallback); + + meterListener.Start(); + } + + /// + /// Example of advanced distributed tracing configuration in Application Insights + /// using to attach for events. + /// + /// Instance of for tracing configuration. + /// Instance of Application Insights . + private static void ConfigureTracing(ActivityListener activityListener, TelemetryClient telemetryClient) + { + var operations = new ConcurrentDictionary>(); + + // For more detailed tracing we need to attach Activity entity to Application Insights operation manually. + Action activityStarted = activity => + { + var operation = telemetryClient.StartOperation(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 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 _) => ActivitySamplingResult.AllData; + activityListener.SampleUsingParentId = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData; + activityListener.ActivityStarted = activityStarted; + activityListener.ActivityStopped = activityStopped; + + ActivitySource.AddActivityListener(activityListener); + } +} diff --git a/dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs b/dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs new file mode 100644 index 000000000000..e24da8fd7b20 --- /dev/null +++ b/dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs @@ -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 +{ + /// + /// Simple helper used to load env vars and secrets like credentials, + /// to avoid hard coding them in the sample code + /// + /// Secret name / Env var name + /// Value found in Secret Manager or Environment Variable + internal static string Var(string name) + { + var configuration = new ConfigurationBuilder() + .AddUserSecrets() + .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; + } +} diff --git a/dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs b/dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs new file mode 100644 index 000000000000..dc15dfed4472 --- /dev/null +++ b/dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs @@ -0,0 +1,39 @@ +// Copyright (c) Microsoft. All rights reserved. + +using System.IO; +using System.Reflection; + +internal static class RepoFiles +{ + /// + /// Scan the local folders from the repo, looking for "samples/skills" folder. + /// + /// The full path to samples/skills + 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; + } +} diff --git a/dotnet/samples/KernelSyntaxExamples/Example12_SequentialPlanner.cs b/dotnet/samples/KernelSyntaxExamples/Example12_SequentialPlanner.cs index 4f2b1be5d49b..15f1b557db00 100644 --- a/dotnet/samples/KernelSyntaxExamples/Example12_SequentialPlanner.cs +++ b/dotnet/samples/KernelSyntaxExamples/Example12_SequentialPlanner.cs @@ -92,7 +92,7 @@ private static async Task PoetrySamplesAsync() // - 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 @@ private static async Task EmailSamplesAsync() // - 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 @@ private static async Task BookSamplesAsync() // - 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 @@ private static async Task MemorySampleAsync() 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) diff --git a/dotnet/samples/KernelSyntaxExamples/Example31_CustomPlanner.cs b/dotnet/samples/KernelSyntaxExamples/Example31_CustomPlanner.cs index c8116c00b1bd..13a7ca482224 100644 --- a/dotnet/samples/KernelSyntaxExamples/Example31_CustomPlanner.cs +++ b/dotnet/samples/KernelSyntaxExamples/Example31_CustomPlanner.cs @@ -147,7 +147,7 @@ public async Task RunMarkupAsync(string docString, SKContext context) 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(); diff --git a/dotnet/samples/KernelSyntaxExamples/Example48_GroundednessChecks.cs b/dotnet/samples/KernelSyntaxExamples/Example48_GroundednessChecks.cs index 91765b85e5df..f82f7fb8d385 100644 --- a/dotnet/samples/KernelSyntaxExamples/Example48_GroundednessChecks.cs +++ b/dotnet/samples/KernelSyntaxExamples/Example48_GroundednessChecks.cs @@ -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); diff --git a/dotnet/samples/KernelSyntaxExamples/RepoUtils/PlanExtensions.cs b/dotnet/samples/KernelSyntaxExamples/RepoUtils/PlanExtensions.cs index eb92d176a534..792faf150ebb 100644 --- a/dotnet/samples/KernelSyntaxExamples/RepoUtils/PlanExtensions.cs +++ b/dotnet/samples/KernelSyntaxExamples/RepoUtils/PlanExtensions.cs @@ -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(); } } diff --git a/dotnet/samples/KernelSyntaxExamples/Skills/EmailSkill.cs b/dotnet/samples/KernelSyntaxExamples/Skills/EmailSkill.cs index c340aa445624..0a029cdae571 100644 --- a/dotnet/samples/KernelSyntaxExamples/Skills/EmailSkill.cs +++ b/dotnet/samples/KernelSyntaxExamples/Skills/EmailSkill.cs @@ -20,7 +20,9 @@ public string GetEmailAddress( [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 "johndoe1234@example.com"; } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/AzureOpenAIClientBase.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/AzureOpenAIClientBase.cs index c0bcc291fa86..4663f1bd8cf1 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/AzureOpenAIClientBase.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/AzureOpenAIClientBase.cs @@ -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 @@ private protected AzureOpenAIClientBase( 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 @@ private protected AzureOpenAIClientBase( 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 @@ private protected AzureOpenAIClientBase( this.ModelId = modelId; this.Client = openAIClient; } + + /// + /// Logs Azure OpenAI action details. + /// + /// Caller member name. Populated automatically by runtime. + private protected void LogActionDetails([CallerMemberName] string? callerMemberName = default) + { + this.Logger.LogInformation("Action: {Action}. Azure OpenAI Deployment Name: {DeploymentName}.", callerMemberName, this.ModelId); + } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/ClientBase.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/ClientBase.cs index 8fb4870c79b1..8e7bf450d1ed 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/ClientBase.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/ClientBase.cs @@ -8,6 +8,8 @@ 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; + } /// /// Model Id or Deployment Name @@ -37,6 +42,11 @@ private protected ClientBase() { } /// private protected abstract OpenAIClient Client { get; } + /// + /// Logger instance + /// + private protected ILogger Logger { get; set; } + /// /// Creates completions for the prompt and settings. /// diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/OpenAIClientBase.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/OpenAIClientBase.cs index 76784dc29dfb..25750230dbf7 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/OpenAIClientBase.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/AzureSdk/OpenAIClientBase.cs @@ -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 @@ private protected OpenAIClientBase( 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 @@ private protected OpenAIClientBase( this.Client = new OpenAIClient(apiKey, options); } + + /// + /// Logs OpenAI action details. + /// + /// Caller member name. Populated automatically by runtime. + private protected void LogActionDetails([CallerMemberName] string? callerMemberName = default) + { + this.Logger.LogInformation("Action: {Action}. OpenAI Model ID: {ModelId}.", callerMemberName, this.ModelId); + } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/AzureChatCompletion.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/AzureChatCompletion.cs index 880fe8eeb1b5..27838f2a8f49 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/AzureChatCompletion.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/AzureChatCompletion.cs @@ -72,6 +72,7 @@ public Task> GetChatCompletionsAsync( ChatRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatResultsAsync(chat, requestSettings, cancellationToken); } @@ -81,6 +82,7 @@ public IAsyncEnumerable GetStreamingChatCompletionsAsync( ChatRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatStreamingResultsAsync(chat, requestSettings, cancellationToken); } @@ -96,6 +98,7 @@ public IAsyncEnumerable GetStreamingCompletionsAsync( CompleteRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatStreamingResultsAsTextAsync(text, requestSettings, cancellationToken); } @@ -105,6 +108,7 @@ public Task> GetCompletionsAsync( CompleteRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatResultsAsTextAsync(text, requestSettings, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/OpenAIChatCompletion.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/OpenAIChatCompletion.cs index 897bfaa8fb89..d444125bff98 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/OpenAIChatCompletion.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/ChatCompletion/OpenAIChatCompletion.cs @@ -41,6 +41,7 @@ public Task> GetChatCompletionsAsync( ChatRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatResultsAsync(chat, requestSettings, cancellationToken); } @@ -50,6 +51,7 @@ public IAsyncEnumerable GetStreamingChatCompletionsAsync( ChatRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatStreamingResultsAsync(chat, requestSettings, cancellationToken); } @@ -65,6 +67,7 @@ public IAsyncEnumerable GetStreamingCompletionsAsync( CompleteRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatStreamingResultsAsTextAsync(text, requestSettings, cancellationToken); } @@ -74,6 +77,7 @@ public Task> GetCompletionsAsync( CompleteRequestSettings? requestSettings = null, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetChatResultsAsTextAsync(text, requestSettings, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/CustomClient/OpenAIClientBase.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/CustomClient/OpenAIClientBase.cs index 70f60fae670b..4dcadc3c02ff 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/CustomClient/OpenAIClientBase.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/CustomClient/OpenAIClientBase.cs @@ -93,7 +93,7 @@ private protected async Task> ExecuteImageGenerationRequestAsync( } 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 @@ private protected async Task ExecuteRequestAsync(string url 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) { diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/AzureTextCompletion.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/AzureTextCompletion.cs index 1df039937938..26350604742c 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/AzureTextCompletion.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/AzureTextCompletion.cs @@ -71,6 +71,7 @@ public IAsyncEnumerable GetStreamingCompletionsAsync( CompleteRequestSettings requestSettings, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetTextStreamingResultsAsync(text, requestSettings, cancellationToken); } @@ -80,6 +81,7 @@ public Task> GetCompletionsAsync( CompleteRequestSettings requestSettings, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetTextResultsAsync(text, requestSettings, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/OpenAITextCompletion.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/OpenAITextCompletion.cs index 8636156d4180..0c9bcc0f28e4 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/OpenAITextCompletion.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextCompletion/OpenAITextCompletion.cs @@ -40,6 +40,7 @@ public IAsyncEnumerable GetStreamingCompletionsAsync( CompleteRequestSettings requestSettings, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetTextStreamingResultsAsync(text, requestSettings, cancellationToken); } @@ -49,6 +50,7 @@ public Task> GetCompletionsAsync( CompleteRequestSettings requestSettings, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetTextResultsAsync(text, requestSettings, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/AzureTextEmbeddingGeneration.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/AzureTextEmbeddingGeneration.cs index 08333a0367ea..3f7b50959610 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/AzureTextEmbeddingGeneration.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/AzureTextEmbeddingGeneration.cs @@ -60,6 +60,7 @@ public Task>> GenerateEmbeddingsAsync( IList data, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetEmbeddingsAsync(data, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/OpenAITextEmbeddingGeneration.cs b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/OpenAITextEmbeddingGeneration.cs index 737f20907d3f..4f41aae08b9f 100644 --- a/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/OpenAITextEmbeddingGeneration.cs +++ b/dotnet/src/Connectors/Connectors.AI.OpenAI/TextEmbedding/OpenAITextEmbeddingGeneration.cs @@ -43,6 +43,7 @@ public Task>> GenerateEmbeddingsAsync( IList data, CancellationToken cancellationToken = default) { + this.LogActionDetails(); return this.InternalGetEmbeddingsAsync(data, cancellationToken); } } diff --git a/dotnet/src/Connectors/Connectors.Memory.CosmosDB/CosmosMemoryStore.cs b/dotnet/src/Connectors/Connectors.Memory.CosmosDB/CosmosMemoryStore.cs index ebfc40d8b04d..3a6d6d9f0a9a 100644 --- a/dotnet/src/Connectors/Connectors.Memory.CosmosDB/CosmosMemoryStore.cs +++ b/dotnet/src/Connectors/Connectors.Memory.CosmosDB/CosmosMemoryStore.cs @@ -52,11 +52,11 @@ public static async Task CreateAsync(CosmosClient client, str 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 async Task CreateCollectionAsync(string collectionName, CancellationToken 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 async Task UpsertAsync(string collectionName, MemoryRecord record 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 async Task RemoveAsync(string collectionName, string key, CancellationTok if (response.StatusCode == HttpStatusCode.OK) { - this._log.LogInformation("Record deleted from {0}", collectionName); + this._log.LogDebug("Record deleted from {0}", collectionName); } else { diff --git a/dotnet/src/Connectors/Connectors.Memory.Pinecone/PineconeClient.cs b/dotnet/src/Connectors/Connectors.Memory.Pinecone/PineconeClient.cs index f5fdf2192d0c..8089c1d62cc8 100644 --- a/dotnet/src/Connectors/Connectors.Memory.Pinecone/PineconeClient.cs +++ b/dotnet/src/Connectors/Connectors.Memory.Pinecone/PineconeClient.cs @@ -47,7 +47,7 @@ public PineconeClient(string pineconeEnvironment, string apiKey, ILogger? logger 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 PineconeClient(string pineconeEnvironment, string apiKey, ILogger? logger 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 PineconeClient(string pineconeEnvironment, string apiKey, ILogger? logger Dictionary? 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 async Task UpsertAsync( 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 async Task UpsertAsync( 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 async Task DeleteAsync( .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 async Task DeleteAsync( /// 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 async Task UpdateAsync(string indexName, PineconeDocument document, strin /// 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 async Task CreateIndexAsync(IndexDefinition indexDefinition, Cancellation /// 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 async Task DeleteIndexAsync(string indexName, CancellationToken cancellat throw; } - this._logger.LogInformation("Index: {0} has been successfully deleted.", indexName); + this._logger.LogDebug("Index: {0} has been successfully deleted.", indexName); } /// public async Task DoesIndexExistAsync(string indexName, CancellationToken cancellationToken = default) { - this._logger.LogInformation("Checking for index {0}", indexName); + this._logger.LogDebug("Checking for index {0}", indexName); List? indexNames = await this.ListIndexesAsync(cancellationToken).ToListAsync(cancellationToken).ConfigureAwait(false); @@ -558,9 +558,14 @@ private string GetIndexOperationsApiBasePath() 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 @@ private async Task GetIndexHostAsync(string indexName, CancellationToken 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 @@ private async Task GetIndexHostAsync(string indexName, CancellationToken $"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); diff --git a/dotnet/src/Connectors/Connectors.Memory.Qdrant/QdrantVectorDbClient.cs b/dotnet/src/Connectors/Connectors.Memory.Qdrant/QdrantVectorDbClient.cs index 01b235d32c2a..bbd70d7cbef3 100644 --- a/dotnet/src/Connectors/Connectors.Memory.Qdrant/QdrantVectorDbClient.cs +++ b/dotnet/src/Connectors/Connectors.Memory.Qdrant/QdrantVectorDbClient.cs @@ -459,13 +459,14 @@ private static Uri SanitizeEndpoint(string endpoint, int? port = null) 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); diff --git a/dotnet/src/Connectors/Connectors.Memory.Weaviate/WeaviateMemoryStore.cs b/dotnet/src/Connectors/Connectors.Memory.Weaviate/WeaviateMemoryStore.cs index 027b310f5b43..52ceb58a05c9 100644 --- a/dotnet/src/Connectors/Connectors.Memory.Weaviate/WeaviateMemoryStore.cs +++ b/dotnet/src/Connectors/Connectors.Memory.Weaviate/WeaviateMemoryStore.cs @@ -104,7 +104,7 @@ public async Task CreateCollectionAsync(string collectionName, CancellationToken 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 async Task CreateCollectionAsync(string collectionName, CancellationToken $"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 async Task DoesCollectionExistAsync(string collectionName, Cancella 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 async Task DoesCollectionExistAsync(string collectionName, Cancella 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 async Task DoesCollectionExistAsync(string collectionName, Cancella /// public async IAsyncEnumerable 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 async Task DeleteCollectionAsync(string collectionName, CancellationToken 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 async IAsyncEnumerable UpsertBatchAsync(string collectionName, IE { 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 async IAsyncEnumerable UpsertBatchAsync(string collectionName, IE embedding: new(weaviateObject.Vector ?? Array.Empty()), 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 async Task RemoveAsync(string collectionName, string key, CancellationTok 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 async Task RemoveAsync(string collectionName, string key, CancellationTok { (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 async Task RemoveBatchAsync(string collectionName, IEnumerable ke 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 @@ private static string ToWeaviateFriendlyClassName(string collectionName) 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); } diff --git a/dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs b/dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs new file mode 100644 index 000000000000..23ee168f55f1 --- /dev/null +++ b/dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs @@ -0,0 +1,19 @@ +// Copyright (c) Microsoft. All rights reserved. + +using System.Threading.Tasks; + +namespace Microsoft.SemanticKernel.Planning.Sequential; + +/// +/// Interface for planner that uses semantic function to create a sequential plan. +/// +public interface ISequentialPlanner +{ + /// + /// Create a plan for a goal. + /// + /// The goal to create a plan for. + /// The plan. + /// Thrown when the plan cannot be created. + Task CreatePlanAsync(string goal); +} diff --git a/dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs b/dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs new file mode 100644 index 000000000000..7a0326241a7e --- /dev/null +++ b/dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs @@ -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; + +/// +/// Instrumented planner that uses semantic function to create a sequential plan. +/// Captures planner-related logs and metrics. +/// +public sealed class InstrumentedSequentialPlanner : ISequentialPlanner +{ + /// + /// Initialize a new instance of the class. + /// + /// Instance of to decorate. + /// Optional logger. + public InstrumentedSequentialPlanner( + ISequentialPlanner planner, + ILogger? logger = null) + { + this._planner = planner; + this._logger = logger ?? NullLogger.Instance; + } + + /// + public async Task 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; + + /// + /// Instance of for planner-related activities. + /// + private static ActivitySource s_activitySource = new(typeof(InstrumentedSequentialPlanner).FullName); + + /// + /// Instance of for planner-related metrics. + /// + private static Meter s_meter = new(typeof(InstrumentedSequentialPlanner).FullName); + + /// + /// Instance of to record plan creation execution time. + /// + private static Histogram s_createPlanExecutionTime = + s_meter.CreateHistogram( + name: "SK.SequentialPlanner.CreatePlan.ExecutionTime", + unit: "ms", + description: "Execution time of plan creation"); + + #endregion +} diff --git a/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlanner.cs b/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlanner.cs index bf272d6f6219..5c9c8179f319 100644 --- a/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlanner.cs +++ b/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlanner.cs @@ -15,7 +15,7 @@ namespace Microsoft.SemanticKernel.Planning; /// /// A planner that uses semantic function to create a sequential plan. /// -public sealed class SequentialPlanner +public sealed class SequentialPlanner : ISequentialPlanner { private const string StopSequence = ""; @@ -49,12 +49,7 @@ public SequentialPlanner( this._context = kernel.CreateNewContext(); } - /// - /// Create a plan for a goal. - /// - /// The goal to create a plan for. - /// The plan. - /// Thrown when the plan cannot be created. + /// public async Task CreatePlanAsync(string goal) { if (string.IsNullOrEmpty(goal)) diff --git a/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlannerExtensions.cs b/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlannerExtensions.cs new file mode 100644 index 000000000000..4b212c618c8a --- /dev/null +++ b/dotnet/src/Extensions/Planning.SequentialPlanner/SequentialPlannerExtensions.cs @@ -0,0 +1,21 @@ +// Copyright (c) Microsoft. All rights reserved. + +using Microsoft.Extensions.Logging; + +namespace Microsoft.SemanticKernel.Planning.Sequential; + +/// +/// Extension methods for class. +/// +public static class SequentialPlannerExtensions +{ + /// + /// Returns decorated instance of with enabled instrumentation. + /// + /// Instance of to decorate. + /// Optional logger. + public static ISequentialPlanner WithInstrumentation(this ISequentialPlanner planner, ILogger? logger = null) + { + return new InstrumentedSequentialPlanner(planner, logger); + } +} diff --git a/dotnet/src/IntegrationTests/Fakes/EmailSkillFake.cs b/dotnet/src/IntegrationTests/Fakes/EmailSkillFake.cs index 695f265dd87d..5b54f167b9cd 100644 --- a/dotnet/src/IntegrationTests/Fakes/EmailSkillFake.cs +++ b/dotnet/src/IntegrationTests/Fakes/EmailSkillFake.cs @@ -25,11 +25,11 @@ public Task GetEmailAddressAsync( { 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("johndoe1234@example.com"); } - logger.LogDebug("Returning dynamic email for {0}", input); + logger.LogTrace("Returning dynamic email for {0}", input); return Task.FromResult($"{input}@example.com"); } diff --git a/dotnet/src/SemanticKernel.Abstractions/Diagnostics/ITelemetryService.cs b/dotnet/src/SemanticKernel.Abstractions/Diagnostics/ITelemetryService.cs deleted file mode 100644 index f7c592ace343..000000000000 --- a/dotnet/src/SemanticKernel.Abstractions/Diagnostics/ITelemetryService.cs +++ /dev/null @@ -1,17 +0,0 @@ -// Copyright (c) Microsoft. All rights reserved. - -namespace Microsoft.SemanticKernel.Diagnostics; - -/// -/// Interface for common telemetry events to track actions across the semantic kernel. -/// -public interface ITelemetryService -{ - /// - /// Creates a telemetry event when a skill function is executed. - /// - /// Name of the skill - /// Skill function name - /// If the skill executed successfully - void TrackSkillFunction(string skillName, string functionName, bool success); -} diff --git a/dotnet/src/SemanticKernel/Planning/Plan.cs b/dotnet/src/SemanticKernel/Planning/Plan.cs index 541fc2a38b49..684dc88bee7a 100644 --- a/dotnet/src/SemanticKernel/Planning/Plan.cs +++ b/dotnet/src/SemanticKernel/Planning/Plan.cs @@ -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 Task RunNextStepAsync(IKernel kernel, ContextVariables variables, C kernel.Skills, kernel.Log, cancellationToken); + return this.InvokeNextStepAsync(context); } @@ -250,7 +253,13 @@ public async Task InvokeNextStepAsync(SKContext context) 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 async Task InvokeAsync( { 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 @@ private ContextVariables GetNextStepVariables(ContextVariables variables, Plan s return stepVariables; } + private async Task 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( + 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 @@ private string DebuggerDisplay return display; } } + + #region Instrumentation + + private const string StepExecutionTimeMetricFormat = "SK.{0}.{1}.ExecutionTime"; + + /// + /// Instance of for plan-related activities. + /// + private static ActivitySource s_activitySource = new(typeof(Plan).FullName); + + /// + /// Instance of for planner-related metrics. + /// + private static Meter s_meter = new(typeof(Plan).FullName); + + #endregion } diff --git a/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs b/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs new file mode 100644 index 000000000000..c2b134577ae5 --- /dev/null +++ b/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs @@ -0,0 +1,69 @@ +// Copyright (c) Microsoft. All rights reserved. + +using System.Linq; + +namespace Microsoft.SemanticKernel.Planning; + +/// +/// Extension methods for type. +/// +public static class PlanExtensions +{ + /// + /// Constructs string representation of without sensitive data. + /// + /// Instance of for string construction. + /// Optional indentation. + 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; + } + + /// + /// Constructs string representation of . + /// + /// Instance of for string construction. + /// Optional indentation. + 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; + } +} diff --git a/dotnet/src/SemanticKernel/SemanticKernel.csproj b/dotnet/src/SemanticKernel/SemanticKernel.csproj index 65428d996429..32764f5e4829 100644 --- a/dotnet/src/SemanticKernel/SemanticKernel.csproj +++ b/dotnet/src/SemanticKernel/SemanticKernel.csproj @@ -25,6 +25,10 @@ + + + + diff --git a/dotnet/src/SemanticKernel/TemplateEngine/Blocks/CodeBlock.cs b/dotnet/src/SemanticKernel/TemplateEngine/Blocks/CodeBlock.cs index 76e7d16ad9e0..7f99ff12e2fe 100644 --- a/dotnet/src/SemanticKernel/TemplateEngine/Blocks/CodeBlock.cs +++ b/dotnet/src/SemanticKernel/TemplateEngine/Blocks/CodeBlock.cs @@ -119,8 +119,9 @@ private async Task RenderFunctionCallAsync(FunctionIdBlock fBlock, SKCon // 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); diff --git a/dotnet/src/SemanticKernel/TemplateEngine/PromptTemplateEngine.cs b/dotnet/src/SemanticKernel/TemplateEngine/PromptTemplateEngine.cs index e78acd69ae6c..ac990cf4c407 100644 --- a/dotnet/src/SemanticKernel/TemplateEngine/PromptTemplateEngine.cs +++ b/dotnet/src/SemanticKernel/TemplateEngine/PromptTemplateEngine.cs @@ -91,8 +91,9 @@ public async Task RenderAsync(IList blocks, SKContext context) 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(); } diff --git a/dotnet/src/Skills/Skills.Core/TextMemorySkill.cs b/dotnet/src/Skills/Skills.Core/TextMemorySkill.cs index 89d4322f6249..2b08d0cb5dde 100644 --- a/dotnet/src/Skills/Skills.Core/TextMemorySkill.cs +++ b/dotnet/src/Skills/Skills.Core/TextMemorySkill.cs @@ -74,7 +74,7 @@ public async Task RetrieveAsync( 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 async Task RecallAsync( 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 memories = await context.Memory @@ -119,7 +119,7 @@ public async Task RecallAsync( 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 async Task SaveAsync( 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 async Task RemoveAsync( 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); } diff --git a/dotnet/src/Skills/Skills.Document/DocumentSkill.cs b/dotnet/src/Skills/Skills.Document/DocumentSkill.cs index 21429d7d3ba1..b88e68cac813 100644 --- a/dotnet/src/Skills/Skills.Document/DocumentSkill.cs +++ b/dotnet/src/Skills/Skills.Document/DocumentSkill.cs @@ -75,7 +75,7 @@ public async Task ReadTextAsync( [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 async Task AppendTextAsync( // 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); } } diff --git a/dotnet/src/Skills/Skills.MsGraph/CalendarSkill.cs b/dotnet/src/Skills/Skills.MsGraph/CalendarSkill.cs index cca4ba9ccc00..63f34d2510ac 100644 --- a/dotnet/src/Skills/Skills.MsGraph/CalendarSkill.cs +++ b/dotnet/src/Skills/Skills.MsGraph/CalendarSkill.cs @@ -111,7 +111,8 @@ public async Task AddEventAsync( Attendees = attendees is not null ? attendees.Split(new[] { ',', ';' }, StringSplitOptions.RemoveEmptyEntries) : Enumerable.Empty(), }; - 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 async Task GetCalendarEventsAsync( [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"; diff --git a/dotnet/src/Skills/Skills.MsGraph/CloudDriveSkill.cs b/dotnet/src/Skills/Skills.MsGraph/CloudDriveSkill.cs index 6ad6070c3f8e..572d8317f2b1 100644 --- a/dotnet/src/Skills/Skills.MsGraph/CloudDriveSkill.cs +++ b/dotnet/src/Skills/Skills.MsGraph/CloudDriveSkill.cs @@ -53,7 +53,7 @@ public async Task GetFileContentAsync( using StreamReader sr = new(fileContentStream); string content = await sr.ReadToEndAsync().ConfigureAwait(false); - this._logger.LogDebug("File content: {0}", content); + return content; } diff --git a/dotnet/src/Skills/Skills.MsGraph/EmailSkill.cs b/dotnet/src/Skills/Skills.MsGraph/EmailSkill.cs index 45cd5298377f..f6f7222d686b 100644 --- a/dotnet/src/Skills/Skills.MsGraph/EmailSkill.cs +++ b/dotnet/src/Skills/Skills.MsGraph/EmailSkill.cs @@ -95,7 +95,8 @@ public async Task SendEmailAsync( 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 async Task GetEmailMessagesAsync( [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"; diff --git a/dotnet/src/Skills/Skills.MsGraph/TaskListSkill.cs b/dotnet/src/Skills/Skills.MsGraph/TaskListSkill.cs index 76781c304a8a..550f1d6dadd7 100644 --- a/dotnet/src/Skills/Skills.MsGraph/TaskListSkill.cs +++ b/dotnet/src/Skills/Skills.MsGraph/TaskListSkill.cs @@ -90,7 +90,9 @@ public async Task AddTaskAsync( 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); } diff --git a/dotnet/src/Skills/Skills.OpenAPI/Extensions/KernelOpenApiExtensions.cs b/dotnet/src/Skills/Skills.OpenAPI/Extensions/KernelOpenApiExtensions.cs index ed63cdbb14de..e18515c10458 100644 --- a/dotnet/src/Skills/Skills.OpenAPI/Extensions/KernelOpenApiExtensions.cs +++ b/dotnet/src/Skills/Skills.OpenAPI/Extensions/KernelOpenApiExtensions.cs @@ -335,7 +335,7 @@ private static string ConvertOperationIdToValidFunctionName(string operationId, 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; } diff --git a/dotnet/src/Skills/Skills.Web/Bing/BingConnector.cs b/dotnet/src/Skills/Skills.Web/Bing/BingConnector.cs index 2458492337dd..a9e52a55e5d9 100644 --- a/dotnet/src/Skills/Skills.Web/Bing/BingConnector.cs +++ b/dotnet/src/Skills/Skills.Web/Bing/BingConnector.cs @@ -69,6 +69,8 @@ public async Task> SearchAsync(string query, int count = 1, 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(json); diff --git a/samples/dotnet/openapi-skills/Program.cs b/samples/dotnet/openapi-skills/Program.cs index 82919e89904f..8e4879242fe8 100644 --- a/samples/dotnet/openapi-skills/Program.cs +++ b/samples/dotnet/openapi-skills/Program.cs @@ -213,11 +213,11 @@ private static bool TryExtractJsonFromOpenApiPlanResult(string openApiSkillRespo } 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;