From 5bd3b7dad4174a8e6dbf26abcbc0d5f78ad33f97 Mon Sep 17 00:00:00 2001 From: "Ricardo Minguez Pablos (RIDO)" Date: Fri, 20 Mar 2026 16:39:52 -0700 Subject: [PATCH] Add guarded logging extensions and apply throughout codebase Introduce LoggerExtensions with LogInformationGuarded and LogTraceGuarded to prevent expensive log message construction when not enabled. Replace direct LogInformation and LogTrace calls with guarded versions in core classes. Remove CA1873 suppression and update CA2227 justification. Improves logging performance and consistency. --- .../BotApplication.cs | 11 +-- .../ConversationClient.cs | 32 ++++---- .../GlobalSuppressions.cs | 8 +- .../Hosting/JwtExtensions.cs | 6 +- .../Http/BotHttpClient.cs | 3 +- .../LoggerExtensions.cs | 75 +++++++++++++++++++ .../UserTokenClient.cs | 19 +++-- 7 files changed, 116 insertions(+), 38 deletions(-) create mode 100644 core/src/Microsoft.Teams.Bot.Core/LoggerExtensions.cs 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,