Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Guard logging calls to avoid unnecessary work at call site #2164

Merged
merged 1 commit into from
Jul 28, 2023
Merged

Guard logging calls to avoid unnecessary work at call site #2164

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
51 changes: 34 additions & 17 deletions src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs
View file
Open in desktop
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))
stephentoub marked this conversation as resolved.
Show resolved Hide resolved
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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