Skip to content

Commit

Permalink
Guard logging calls to avoid unnecessary work at call site (#2164)
Browse files Browse the repository at this point in the history 
Many LogHelper.Log calls are doing work at the call site, such as allocating params arrays, boxing structs, formatting strings, and so on, even when the data will be thrown away because logging (or logging for that verbosity level) isn't enabled.  This adds an IsEnabled method to LogHelper and uses it at any call site where there's such work to be avoided.
  • Loading branch information
@stephentoub
stephentoub authored Jul 28, 2023
1 parent f2e0763 commit 12d2f88
Show file tree
Hide file tree
Showing 23 changed files with 270 additions and 98 deletions.
51 changes: 34 additions & 17 deletions src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@
using System.Text.RegularExpressions;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.IdentityModel.Abstractions;
using Microsoft.IdentityModel.Logging;
using Microsoft.IdentityModel.Tokens;
using Newtonsoft.Json;
Expand Down Expand Up @@ -158,7 +159,9 @@ public virtual bool CanReadToken(string token)

if (token.Length > MaximumTokenSizeInBytes)
{
LogHelper.LogInformation(TokenLogMessages.IDX10209, LogHelper.MarkAsNonPII(token.Length), LogHelper.MarkAsNonPII(MaximumTokenSizeInBytes));
if (LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(TokenLogMessages.IDX10209, LogHelper.MarkAsNonPII(token.Length), LogHelper.MarkAsNonPII(MaximumTokenSizeInBytes));

return false;
}

Expand Down Expand Up @@ -337,9 +340,12 @@ public virtual string CreateToken(SecurityTokenDescriptor tokenDescriptor)
if (tokenDescriptor == null)
throw LogHelper.LogArgumentNullException(nameof(tokenDescriptor));

if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
if (LogHelper.IsEnabled(EventLogLevel.Warning))
{
if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
}

JObject payload;
if (tokenDescriptor.Subject != null)
Expand All @@ -354,39 +360,39 @@ public virtual string CreateToken(SecurityTokenDescriptor tokenDescriptor)

if (tokenDescriptor.Audience != null)
{
if (payload.ContainsKey(JwtRegisteredClaimNames.Aud))
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Aud))
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Audience))));

payload[JwtRegisteredClaimNames.Aud] = tokenDescriptor.Audience;
}

if (tokenDescriptor.Expires.HasValue)
{
if (payload.ContainsKey(JwtRegisteredClaimNames.Exp))
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Exp))
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Expires))));

payload[JwtRegisteredClaimNames.Exp] = EpochTime.GetIntDate(tokenDescriptor.Expires.Value);
}

if (tokenDescriptor.Issuer != null)
{
if (payload.ContainsKey(JwtRegisteredClaimNames.Iss))
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iss))
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Issuer))));

payload[JwtRegisteredClaimNames.Iss] = tokenDescriptor.Issuer;
}

if (tokenDescriptor.IssuedAt.HasValue)
{
if (payload.ContainsKey(JwtRegisteredClaimNames.Iat))
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iat))
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.IssuedAt))));

payload[JwtRegisteredClaimNames.Iat] = EpochTime.GetIntDate(tokenDescriptor.IssuedAt.Value);
}

if (tokenDescriptor.NotBefore.HasValue)
{
if (payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.NotBefore))));

payload[JwtRegisteredClaimNames.Nbf] = EpochTime.GetIntDate(tokenDescriptor.NotBefore.Value);
Expand Down Expand Up @@ -698,7 +704,8 @@ private string CreateTokenPrivate(
}
catch(Exception ex)
{
LogHelper.LogExceptionMessage(new SecurityTokenException(LogHelper.FormatInvariant(LogMessages.IDX14307, ex, payload)));
if (LogHelper.IsEnabled(EventLogLevel.Error))
LogHelper.LogExceptionMessage(new SecurityTokenException(LogHelper.FormatInvariant(LogMessages.IDX14307, ex, payload)));
}

payload = jsonPayload != null ? jsonPayload.ToString(Formatting.None) : payload;
Expand Down Expand Up @@ -841,7 +848,9 @@ private static string GetActualIssuer(JsonWebToken jwtToken)
string actualIssuer = jwtToken.Issuer;
if (string.IsNullOrWhiteSpace(actualIssuer))
{
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);

actualIssuer = ClaimsIdentity.DefaultIssuer;
}

Expand Down Expand Up @@ -1136,12 +1145,13 @@ internal IEnumerable<SecurityKey> GetContentEncryptionKeys(JsonWebToken jwtToken
var key = ResolveTokenDecryptionKey(jwtToken.EncodedToken, jwtToken, validationParameters);
if (key != null)
{
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
if (LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
}
else if (configuration != null)
{
key = ResolveTokenDecryptionKeyFromConfig(jwtToken, configuration);
if ( key != null )
if (key != null && LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(TokenLogMessages.IDX10905, key);
}

Expand Down Expand Up @@ -1465,7 +1475,8 @@ private async ValueTask<TokenValidationResult> ValidateTokenAsync(JsonWebToken j
{
// The exception is not re-thrown as the TokenValidationParameters may have the issuer and signing key set
// directly on them, allowing the library to continue with token validation.
LogHelper.LogWarning(LogHelper.FormatInvariant(TokenLogMessages.IDX10261, validationParameters.ConfigurationManager.MetadataAddress, ex.ToString()));
if (LogHelper.IsEnabled(EventLogLevel.Warning))
LogHelper.LogWarning(LogHelper.FormatInvariant(TokenLogMessages.IDX10261, validationParameters.ConfigurationManager.MetadataAddress, ex.ToString()));
}
}

Expand Down Expand Up @@ -1740,7 +1751,9 @@ private static JsonWebToken ValidateSignature(JsonWebToken jwtToken, TokenValida
{
if (ValidateSignature(jwtToken, key, validationParameters))
{
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);
if (LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);

jwtToken.SigningKey = key;
return jwtToken;
}
Expand Down Expand Up @@ -1823,7 +1836,9 @@ internal static bool ValidateSignature(byte[] encodedBytes, byte[] signature, Se
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
if (!cryptoProviderFactory.IsSupportedAlgorithm(algorithm, key))
{
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);
if (LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);

return false;
}

Expand Down Expand Up @@ -1881,7 +1896,9 @@ internal static bool ValidateSignature(JsonWebToken jsonWebToken, SecurityKey ke
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
if (!cryptoProviderFactory.IsSupportedAlgorithm(jsonWebToken.Alg, key))
{
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);
if (LogHelper.IsEnabled(EventLogLevel.Informational))
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);

return false;
}

Expand Down
17 changes: 13 additions & 4 deletions src/Microsoft.IdentityModel.JsonWebTokens/JwtTokenUtilities.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
using System.Text;
using System.Text.Json;
using System.Text.RegularExpressions;
using Microsoft.IdentityModel.Abstractions;
using Microsoft.IdentityModel.Logging;
using Microsoft.IdentityModel.Tokens;
using Newtonsoft.Json.Linq;
Expand Down Expand Up @@ -97,7 +98,9 @@ public static string CreateEncodedSignature(string input, SigningCredentials sig

try
{
LogHelper.LogVerbose(LogHelper.FormatInvariant(LogMessages.IDX14201, LogHelper.MarkAsNonPII(cacheProvider)));
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
LogHelper.LogVerbose(LogHelper.FormatInvariant(LogMessages.IDX14201, LogHelper.MarkAsNonPII(cacheProvider)));

return Base64UrlEncoder.Encode(signatureProvider.Sign(Encoding.UTF8.GetBytes(input)));
}
finally
Expand Down Expand Up @@ -165,7 +168,9 @@ internal static string DecryptJwtToken(
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
if (cryptoProviderFactory == null)
{
LogHelper.LogWarning(TokenLogMessages.IDX10607, key);
if (LogHelper.IsEnabled(EventLogLevel.Warning))
LogHelper.LogWarning(TokenLogMessages.IDX10607, key);

continue;
}

Expand All @@ -179,8 +184,10 @@ internal static string DecryptJwtToken(
{
if (!cryptoProviderFactory.IsSupportedAlgorithm(jsonWebToken.Enc, key))
{
if (LogHelper.IsEnabled(EventLogLevel.Warning))
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);

algorithmNotSupportedByCryptoProvider = true;
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
continue;
}

Expand All @@ -203,8 +210,10 @@ internal static string DecryptJwtToken(
{
if (!cryptoProviderFactory.IsSupportedAlgorithm(decryptionParameters.Enc, key))
{
if (LogHelper.IsEnabled(EventLogLevel.Warning))
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);

algorithmNotSupportedByCryptoProvider = true;
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
continue;
}

Expand Down
26 changes: 19 additions & 7 deletions src/Microsoft.IdentityModel.Logging/LogHelper.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,15 @@ internal static bool HeaderWritten
set { _isHeaderWritten = value; }
}

/// <summary>
/// Gets whether logging is enabled at the specified <see cref="EventLogLevel"/>."/>
/// </summary>
/// <param name="level">The log level</param>
/// <returns><see langword="true"/> if logging is enabled at the specified level; otherwise, <see langword="false"/>.</returns>
public static bool IsEnabled(EventLogLevel level) =>
Logger.IsEnabled(level) ||
IdentityModelEventSource.Logger.IsEnabled(EventLogLevelToEventLevel(level), EventKeywords.All);

/// <summary>
/// Logs an exception using the event source logger and returns new <see cref="ArgumentNullException"/> exception.
/// </summary>
Expand Down Expand Up @@ -255,7 +264,7 @@ public static Exception LogExceptionMessage(EventLevel eventLevel, Exception exc
if (exception == null)
return null;

if (IdentityModelEventSource.Logger.IsEnabled() && IdentityModelEventSource.Logger.LogLevel >= eventLevel)
if (IdentityModelEventSource.Logger.IsEnabled(eventLevel, EventKeywords.All))
IdentityModelEventSource.Logger.Write(eventLevel, exception.InnerException, exception.Message);

EventLogLevel eventLogLevel = EventLevelToEventLogLevel(eventLevel);
Expand All @@ -272,7 +281,7 @@ public static Exception LogExceptionMessage(EventLevel eventLevel, Exception exc
/// <param name="args">An object array that contains zero or more objects to format.</param>
public static void LogInformation(string message, params object[] args)
{
if (IdentityModelEventSource.Logger.IsEnabled() && IdentityModelEventSource.Logger.LogLevel >= EventLevel.Informational)
if (IdentityModelEventSource.Logger.IsEnabled(EventLevel.Informational, EventKeywords.All))
IdentityModelEventSource.Logger.WriteInformation(message, args);

if (Logger.IsEnabled(EventLogLevel.Informational))
Expand All @@ -286,8 +295,8 @@ public static void LogInformation(string message, params object[] args)
/// <param name="args">An object array that contains zero or more objects to format.</param>
public static void LogVerbose(string message, params object[] args)
{
if (IdentityModelEventSource.Logger.IsEnabled())
IdentityModelEventSource.Logger.WriteVerbose(message, args);
if (IdentityModelEventSource.Logger.IsEnabled(EventLevel.Verbose, EventKeywords.All))
IdentityModelEventSource.Logger.WriteVerbose(message, args);

if (Logger.IsEnabled(EventLogLevel.Verbose))
Logger.Log(WriteEntry(EventLogLevel.Verbose, null, message, args));
Expand All @@ -300,8 +309,8 @@ public static void LogVerbose(string message, params object[] args)
/// <param name="args">An object array that contains zero or more objects to format.</param>
public static void LogWarning(string message, params object[] args)
{
if (IdentityModelEventSource.Logger.IsEnabled())
IdentityModelEventSource.Logger.WriteWarning(message, args);
if (IdentityModelEventSource.Logger.IsEnabled(EventLevel.Warning, EventKeywords.All))
IdentityModelEventSource.Logger.WriteWarning(message, args);

if (Logger.IsEnabled(EventLogLevel.Warning))
Logger.Log(WriteEntry(EventLogLevel.Warning, null, message, args));
Expand All @@ -323,7 +332,7 @@ public static void LogWarning(string message, params object[] args)
else
message = format;

if (IdentityModelEventSource.Logger.IsEnabled() && IdentityModelEventSource.Logger.LogLevel >= eventLevel)
if (IdentityModelEventSource.Logger.IsEnabled(eventLevel, EventKeywords.All))
IdentityModelEventSource.Logger.Write(eventLevel, innerException, message);

EventLogLevel eventLogLevel = EventLevelToEventLogLevel(eventLevel);
Expand All @@ -345,6 +354,9 @@ public static void LogWarning(string message, params object[] args)
private static EventLogLevel EventLevelToEventLogLevel(EventLevel eventLevel) =>
(uint)(int)eventLevel <= 5 ? (EventLogLevel)eventLevel : EventLogLevel.Error;

private static EventLevel EventLogLevelToEventLevel(EventLogLevel eventLevel) =>
(uint)(int)eventLevel <= 5 ? (EventLevel)eventLevel : EventLevel.Error;

/// <summary>
/// Formats the string using InvariantCulture
/// </summary>
Expand Down
5 changes: 3 additions & 2 deletions src/Microsoft.IdentityModel.Logging/TextWriterEventListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
using System;
using System.Diagnostics.Tracing;
using System.IO;
using Microsoft.IdentityModel.Abstractions;

namespace Microsoft.IdentityModel.Logging
{
Expand Down Expand Up @@ -31,7 +32,7 @@ public TextWriterEventListener()
_streamWriter = new StreamWriter(fileStream);
_streamWriter.AutoFlush = true;
}
catch (Exception ex)
catch (Exception ex) when (LogHelper.IsEnabled(EventLogLevel.Error))
{
LogHelper.LogExceptionMessage(new InvalidOperationException(LogMessages.MIML10001, ex));
throw;
Expand All @@ -53,7 +54,7 @@ public TextWriterEventListener(string filePath)
_streamWriter = new StreamWriter(fileStream);
_streamWriter.AutoFlush = true;
}
catch (Exception ex)
catch (Exception ex) when (LogHelper.IsEnabled(EventLogLevel.Error))
{
LogHelper.LogExceptionMessage(new InvalidOperationException(LogMessages.MIML10001, ex));
throw;
Expand Down
9 changes: 7 additions & 2 deletions ...crosoft.IdentityModel.Protocols.OpenIdConnect/Configuration/OpenIdConnectConfiguration.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Collections.Generic;
using System.Collections.ObjectModel;
using System.ComponentModel;
using Microsoft.IdentityModel.Abstractions;
using Microsoft.IdentityModel.Logging;
using Microsoft.IdentityModel.Tokens;
using Newtonsoft.Json;
Expand All @@ -31,7 +32,9 @@ public static OpenIdConnectConfiguration Create(string json)
if (string.IsNullOrEmpty(json))
throw LogHelper.LogArgumentNullException(nameof(json));

LogHelper.LogVerbose(LogMessages.IDX21808, json);
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
LogHelper.LogVerbose(LogMessages.IDX21808, json);

return new OpenIdConnectConfiguration(json);
}

Expand Down Expand Up @@ -69,7 +72,9 @@ public OpenIdConnectConfiguration(string json)

try
{
LogHelper.LogVerbose(LogMessages.IDX21806, json, LogHelper.MarkAsNonPII(_className));
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
LogHelper.LogVerbose(LogMessages.IDX21806, json, LogHelper.MarkAsNonPII(_className));

JsonConvert.PopulateObject(json, this);
}
catch (Exception ex)
Expand Down
Loading

0 comments on commit 12d2f88

Please sign in to comment.