diff --git a/core/src/Microsoft.Teams.Bot.Core/BotApplication.cs b/core/src/Microsoft.Teams.Bot.Core/BotApplication.cs index c7e181bb..745a1803 100644 --- a/core/src/Microsoft.Teams.Bot.Core/BotApplication.cs +++ b/core/src/Microsoft.Teams.Bot.Core/BotApplication.cs @@ -46,7 +46,7 @@ public BotApplication(ConversationClient conversationClient, UserTokenClient use MiddleWare = new TurnMiddleware(); _conversationClient = conversationClient; _userTokenClient = userTokenClient; - logger.LogInformation("Started {ThisType} listener for AppID:{AppId} with SDK version {SdkVersion}", this.GetType().Name, options.AppId, Version); + logger.LogInformationGuarded("Started {ThisType} listener for AppID:{AppId} with SDK version {SdkVersion}", GetType().Name, options.AppId, Version); } @@ -89,16 +89,13 @@ public virtual async Task ProcessAsync(HttpContext httpContext, CancellationToke CoreActivity activity = await CoreActivity.FromJsonStreamAsync(httpContext.Request.Body, cancellationToken).ConfigureAwait(false) ?? throw new InvalidOperationException("Invalid Activity"); - _logger.LogInformation("Activity received: Type={Type} Id={Id} ServiceUrl={ServiceUrl} MSCV={MSCV}", + _logger.LogInformationGuarded("Activity received: Type={Type} Id={Id} ServiceUrl={ServiceUrl} MSCV={MSCV}", activity.Type, activity.Id, activity.ServiceUrl, httpContext.Request.GetCorrelationVector()); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("Received activity: {Activity}", activity.ToJson()); - } + _logger.LogTraceGuarded("Received activity: {Activity}", activity.ToJson()); // TODO: Replace with structured scope data, ensure it works with OpenTelemetry and other logging providers using (_logger.BeginScope("ActivityType={ActivityType} ActivityId={ActivityId} ServiceUrl={ServiceUrl} MSCV={MSCV}", @@ -116,7 +113,7 @@ public virtual async Task ProcessAsync(HttpContext httpContext, CancellationToke } finally { - _logger.LogInformation("Finished processing activity: Id={Id}", activity.Id); + _logger.LogInformationGuarded("Finished processing activity: Id={Id}", activity.Id); } } } diff --git a/core/src/Microsoft.Teams.Bot.Core/ConversationClient.cs b/core/src/Microsoft.Teams.Bot.Core/ConversationClient.cs index b5ada44a..90c71d1d 100644 --- a/core/src/Microsoft.Teams.Bot.Core/ConversationClient.cs +++ b/core/src/Microsoft.Teams.Bot.Core/ConversationClient.cs @@ -68,11 +68,11 @@ public virtual async Task SendActivityAsync(CoreActivity a url += url.Contains('?', StringComparison.Ordinal) ? "&isTargetedActivity=true" : "?isTargetedActivity=true"; } - logger?.LogInformation("Sending activity to {Url}", url); + logger.LogInformationGuarded("Sending activity to {Url}", url); string body = activity.ToJson(); - logger?.LogTrace("Outgoing Activity :\r {Activity}", body); + logger.LogTraceGuarded("Outgoing Activity :\r {Activity}", body); return (await _botHttpClient.SendAsync( HttpMethod.Post, @@ -108,7 +108,7 @@ public virtual async Task UpdateActivityAsync(string con string body = activity.ToJson(); - logger.LogTrace("Updating activity at {Url}: {Activity}", url, body); + logger.LogTraceGuarded("Updating activity at {Url}: {Activity}", url, body); return (await _botHttpClient.SendAsync( HttpMethod.Put, @@ -142,7 +142,7 @@ public virtual async Task UpdateTargetedActivityAsync(st string body = activity.ToJson(); - logger.LogTrace("Updating targeted activity at {Url}: {Activity}", url, body); + logger.LogTraceGuarded("Updating targeted activity at {Url}: {Activity}", url, body); return (await _botHttpClient.SendAsync( HttpMethod.Put, @@ -205,7 +205,7 @@ public async Task DeleteActivityAsync(string conversationId, string activityId, url += "?isTargetedActivity=true"; } - logger.LogTrace("Deleting activity at {Url}", url); + logger.LogTraceGuarded("Deleting activity at {Url}", url); await _botHttpClient.SendAsync( HttpMethod.Delete, @@ -258,7 +258,7 @@ public virtual async Task> GetConversationMembersAsyn string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/members"; - logger.LogTrace("Getting conversation members from {Url}", url); + logger.LogTraceGuarded("Getting conversation members from {Url}", url); return (await _botHttpClient.SendAsync>( HttpMethod.Get, @@ -292,7 +292,7 @@ public virtual async Task GetConversationMemberAsync(string conversationId string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/members/{Uri.EscapeDataString(userId)}"; - logger.LogTrace("Getting conversation members from {Url}", url); + logger.LogTraceGuarded("Getting conversation member from {Url}", url); return (await _botHttpClient.SendAsync( HttpMethod.Get, @@ -322,7 +322,7 @@ public virtual async Task GetConversationsAsync(Uri se url += $"?continuationToken={Uri.EscapeDataString(continuationToken)}"; } - logger.LogTrace("Getting conversations from {Url}", url); + logger.LogTraceGuarded("Getting conversations from {Url}", url); return (await _botHttpClient.SendAsync( HttpMethod.Get, @@ -351,7 +351,7 @@ public virtual async Task> GetActivityMembersAsync(st string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/activities/{Uri.EscapeDataString(activityId)}/members"; - logger.LogTrace("Getting activity members from {Url}", url); + logger.LogTraceGuarded("Getting activity members from {Url}", url); return (await _botHttpClient.SendAsync>( HttpMethod.Get, @@ -380,7 +380,7 @@ public virtual async Task CreateConversationAsync(Co string paramsJson = JsonSerializer.Serialize(parameters, _jsonSerializerOptions); - logger.LogTrace("Creating conversation at {Url} with parameters: {Parameters}", url, paramsJson); + logger.LogTraceGuarded("Creating conversation at {Url} with parameters: {Parameters}", url, paramsJson); return (await _botHttpClient.SendAsync( HttpMethod.Post, @@ -423,7 +423,7 @@ public virtual async Task GetConversationPagedMembersAsync(s url += $"?{string.Join("&", queryParams)}"; } - logger.LogTrace("Getting paged conversation members from {Url}", url); + logger.LogTraceGuarded("Getting paged conversation members from {Url}", url); return (await _botHttpClient.SendAsync( HttpMethod.Get, @@ -453,7 +453,7 @@ public virtual async Task DeleteConversationMemberAsync(string conversationId, s string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/members/{Uri.EscapeDataString(memberId)}"; - logger.LogTrace("Deleting conversation member at {Url}", url); + logger.LogTraceGuarded("Deleting conversation member at {Url}", url); await _botHttpClient.SendAsync( HttpMethod.Delete, @@ -484,7 +484,7 @@ public virtual async Task SendConversationHisto string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/activities/history"; string transcriptJson = JsonSerializer.Serialize(transcript, _jsonSerializerOptions); - logger.LogTrace("Sending conversation history to {Url}: {Transcript}", url, transcriptJson); + logger.LogTraceGuarded("Sending conversation history to {Url}: {Transcript}", url, transcriptJson); return (await _botHttpClient.SendAsync( HttpMethod.Post, @@ -515,7 +515,7 @@ public virtual async Task UploadAttachmentAsync(string string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/attachments"; string attachmentDataJson = JsonSerializer.Serialize(attachmentData, _jsonSerializerOptions); - logger.LogTrace("Uploading attachment to {Url}: {AttachmentData}", url, attachmentDataJson); + logger.LogTraceGuarded("Uploading attachment to {Url}: {AttachmentData}", url, attachmentDataJson); return (await _botHttpClient.SendAsync( HttpMethod.Post, @@ -546,7 +546,7 @@ public async Task AddReactionAsync(string conversationId, string activityId, str string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/activities/{Uri.EscapeDataString(activityId)}/reactions/{Uri.EscapeDataString(reactionType)}"; - logger.LogTrace("Adding reaction at {Url}", url); + logger.LogTraceGuarded("Adding reaction at {Url}", url); await _botHttpClient.SendAsync( HttpMethod.Put, @@ -577,7 +577,7 @@ public async Task DeleteReactionAsync(string conversationId, string activityId, string url = $"{serviceUrl.ToString().TrimEnd('/')}/v3/conversations/{Uri.EscapeDataString(conversationId)}/activities/{Uri.EscapeDataString(activityId)}/reactions/{Uri.EscapeDataString(reactionType)}"; - logger.LogTrace("Deleting reaction at {Url}", url); + logger.LogTraceGuarded("Deleting reaction at {Url}", url); await _botHttpClient.SendAsync( HttpMethod.Delete, diff --git a/core/src/Microsoft.Teams.Bot.Core/GlobalSuppressions.cs b/core/src/Microsoft.Teams.Bot.Core/GlobalSuppressions.cs index 480d1b6f..0f756969 100644 --- a/core/src/Microsoft.Teams.Bot.Core/GlobalSuppressions.cs +++ b/core/src/Microsoft.Teams.Bot.Core/GlobalSuppressions.cs @@ -3,12 +3,6 @@ using System.Diagnostics.CodeAnalysis; -[assembly: SuppressMessage("Performance", - "CA1873:Avoid potentially expensive logging", - Justification = "", - Scope = "namespaceanddescendants", - Target = "~N:Microsoft.Teams.Bot.Core")] - [assembly: SuppressMessage("Performance", "CA1848:Use the LoggerMessage delegates", Justification = "", @@ -23,6 +17,6 @@ [assembly: SuppressMessage("Usage", "CA2227:Collection properties should be read only", - Justification = "", + Justification = "Required for serialization", Scope = "namespaceanddescendants", Target = "~N:Microsoft.Teams.Bot.Core")] diff --git a/core/src/Microsoft.Teams.Bot.Core/Hosting/JwtExtensions.cs b/core/src/Microsoft.Teams.Bot.Core/Hosting/JwtExtensions.cs index 91e80d6c..3cf22587 100644 --- a/core/src/Microsoft.Teams.Bot.Core/Hosting/JwtExtensions.cs +++ b/core/src/Microsoft.Teams.Bot.Core/Hosting/JwtExtensions.cs @@ -208,7 +208,11 @@ private static AuthenticationBuilder AddTeamsJwtBearer(this AuthenticationBuilde { OnTokenValidated = context => { - GetLogger(context.HttpContext, logger).LogDebug("Token validated for scheme: {Scheme}", schemeName); + GetLogger(context.HttpContext, logger); + if (logger?.IsEnabled(LogLevel.Debug) == true) + { + logger?.LogDebug("Token validated for scheme: {Scheme}", schemeName); + } return Task.CompletedTask; }, OnForbidden = context => diff --git a/core/src/Microsoft.Teams.Bot.Core/Http/BotHttpClient.cs b/core/src/Microsoft.Teams.Bot.Core/Http/BotHttpClient.cs index f972895d..3eae7eb8 100644 --- a/core/src/Microsoft.Teams.Bot.Core/Http/BotHttpClient.cs +++ b/core/src/Microsoft.Teams.Bot.Core/Http/BotHttpClient.cs @@ -8,6 +8,7 @@ using System.Text.Json; using Microsoft.AspNetCore.WebUtilities; using Microsoft.Extensions.Logging; +using Microsoft.Teams.Bot.Core; using Microsoft.Teams.Bot.Core.Hosting; namespace Microsoft.Teams.Bot.Core.Http; @@ -45,7 +46,7 @@ public class BotHttpClient(HttpClient httpClient, ILogger? logger = null) using HttpRequestMessage request = CreateRequest(method, url, body, options); - logger?.LogTrace("Sending HTTP {Method} request to {Url} with body: {Body}", method, url, body); + logger.LogTraceGuarded("Sending HTTP {Method} request to {Url} with body: {Body}", method, url, body); using HttpResponseMessage response = await httpClient.SendAsync(request, cancellationToken).ConfigureAwait(false); diff --git a/core/src/Microsoft.Teams.Bot.Core/LoggerExtensions.cs b/core/src/Microsoft.Teams.Bot.Core/LoggerExtensions.cs new file mode 100644 index 00000000..592cf9d3 --- /dev/null +++ b/core/src/Microsoft.Teams.Bot.Core/LoggerExtensions.cs @@ -0,0 +1,75 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Microsoft.Extensions.Logging; + +namespace Microsoft.Teams.Bot.Core; + +#pragma warning disable CA2254 // Template should be a static expression - by design, these are guarded wrappers +internal static class LoggerExtensions +{ + public static void LogInformationGuarded(this ILogger? logger, string message) + { + if (logger?.IsEnabled(LogLevel.Information) == true) + { + logger.LogInformation(message); + } + } + + public static void LogInformationGuarded(this ILogger? logger, string message, T0 arg0) + { + if (logger?.IsEnabled(LogLevel.Information) == true) + { + logger.LogInformation(message, arg0); + } + } + + public static void LogInformationGuarded(this ILogger? logger, string message, T0 arg0, T1 arg1, T2 arg2) + { + if (logger?.IsEnabled(LogLevel.Information) == true) + { + logger.LogInformation(message, arg0, arg1, arg2); + } + } + + public static void LogInformationGuarded(this ILogger? logger, string message, T0 arg0, T1 arg1, T2 arg2, T3 arg3) + { + if (logger?.IsEnabled(LogLevel.Information) == true) + { + logger.LogInformation(message, arg0, arg1, arg2, arg3); + } + } + + public static void LogTraceGuarded(this ILogger? logger, string message) + { + if (logger?.IsEnabled(LogLevel.Trace) == true) + { + logger.LogTrace(message); + } + } + + public static void LogTraceGuarded(this ILogger? logger, string message, T0 arg0) + { + if (logger?.IsEnabled(LogLevel.Trace) == true) + { + logger.LogTrace(message, arg0); + } + } + + public static void LogTraceGuarded(this ILogger? logger, string message, T0 arg0, T1 arg1) + { + if (logger?.IsEnabled(LogLevel.Trace) == true) + { + logger.LogTrace(message, arg0, arg1); + } + } + + public static void LogTraceGuarded(this ILogger? logger, string message, T0 arg0, T1 arg1, T2 arg2) + { + if (logger?.IsEnabled(LogLevel.Trace) == true) + { + logger.LogTrace(message, arg0, arg1, arg2); + } + } +} +#pragma warning restore CA2254 diff --git a/core/src/Microsoft.Teams.Bot.Core/UserTokenClient.cs b/core/src/Microsoft.Teams.Bot.Core/UserTokenClient.cs index e71e2c50..9f091fc8 100644 --- a/core/src/Microsoft.Teams.Bot.Core/UserTokenClient.cs +++ b/core/src/Microsoft.Teams.Bot.Core/UserTokenClient.cs @@ -51,8 +51,8 @@ public virtual async Task GetTokenStatusAsync(string use { queryParams.Add("include", include); } + _logger.LogInformationGuarded("Calling API endpoint: {Endpoint}", "api/usertoken/GetTokenStatus"); - _logger.LogInformation("Calling API endpoint: {Endpoint}", "api/usertoken/GetTokenStatus"); IList? result = await _botHttpClient.SendAsync>( HttpMethod.Get, _apiEndpoint, @@ -93,7 +93,8 @@ public virtual async Task GetTokenStatusAsync(string use queryParams.Add("code", code); } - _logger.LogInformation("Calling API endpoint: {Endpoint}", "api/usertoken/GetToken"); + _logger.LogInformationGuarded("Calling API endpoint: {Endpoint}", "api/usertoken/GetToken"); + return await _botHttpClient.SendAsync( HttpMethod.Get, _apiEndpoint, @@ -136,7 +137,9 @@ public virtual async Task GetSignInResource(string user queryParams.Add("finalRedirect", finalRedirect); } - _logger.LogInformation("Calling API endpoint: {Endpoint}", "api/botsignin/GetSignInResource"); + _logger.LogInformationGuarded("Calling API endpoint: {Endpoint}", "api/botsignin/GetSignInResource"); + + return (await _botHttpClient.SendAsync( HttpMethod.Get, _apiEndpoint, @@ -169,7 +172,8 @@ public virtual async Task ExchangeTokenAsync(string userId, stri token = exchangeToken }; - _logger.LogInformation("Calling API endpoint: {Endpoint}", "api/usertoken/exchange"); + _logger.LogInformationGuarded("Calling API endpoint: {Endpoint}", "api/usertoken/exchange"); + return (await _botHttpClient.SendAsync( HttpMethod.Post, _apiEndpoint, @@ -205,7 +209,9 @@ public virtual async Task SignOutUserAsync(string userId, string? connectionName queryParams.Add("channelId", channelId); } - _logger.LogInformation("Calling API endpoint: {Endpoint}", "api/usertoken/SignOut"); + _logger.LogInformationGuarded("Calling API endpoint: {Endpoint}", "api/usertoken/SignOut"); + + await _botHttpClient.SendAsync( HttpMethod.Delete, _apiEndpoint, @@ -235,7 +241,8 @@ public virtual async Task> GetAadTokensAsync resourceUrls = resourceUrls ?? [] }; - _logger.LogInformation("Calling API endpoint with POST: {Endpoint}", "api/usertoken/GetAadTokens"); + _logger.LogInformationGuarded("Calling API endpoint with POST: {Endpoint}", "api/usertoken/GetAadTokens"); + return (await _botHttpClient.SendAsync>( HttpMethod.Post, _apiEndpoint,