Skip to content

Commit 9fdc795

Browse files
stephentoubbrentschmaltz
stephentoub
authored and
brentschmaltz
committed
Guard logging calls to avoid unnecessary work at call site (#2164)
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.
1 parent aef1126 commit 9fdc795

File tree

23 files changed

+270
-98
lines changed

23 files changed

+270
-98
lines changed

‎src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs

+34-17
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
using System.Text.RegularExpressions;
1010
using System.Threading;
1111
using System.Threading.Tasks;
12+
using Microsoft.IdentityModel.Abstractions;
1213
using Microsoft.IdentityModel.Logging;
1314
using Microsoft.IdentityModel.Tokens;
1415
using Newtonsoft.Json;
@@ -158,7 +159,9 @@ public virtual bool CanReadToken(string token)
158159

159160
if (token.Length > MaximumTokenSizeInBytes)
160161
{
161-
LogHelper.LogInformation(TokenLogMessages.IDX10209, LogHelper.MarkAsNonPII(token.Length), LogHelper.MarkAsNonPII(MaximumTokenSizeInBytes));
162+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
163+
LogHelper.LogInformation(TokenLogMessages.IDX10209, LogHelper.MarkAsNonPII(token.Length), LogHelper.MarkAsNonPII(MaximumTokenSizeInBytes));
164+
162165
return false;
163166
}
164167

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

340-
if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
341-
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
342-
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
343+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
344+
{
345+
if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
346+
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
347+
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
348+
}
343349

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

355361
if (tokenDescriptor.Audience != null)
356362
{
357-
if (payload.ContainsKey(JwtRegisteredClaimNames.Aud))
363+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Aud))
358364
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Audience))));
359365

360366
payload[JwtRegisteredClaimNames.Aud] = tokenDescriptor.Audience;
361367
}
362368

363369
if (tokenDescriptor.Expires.HasValue)
364370
{
365-
if (payload.ContainsKey(JwtRegisteredClaimNames.Exp))
371+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Exp))
366372
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Expires))));
367373

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

371377
if (tokenDescriptor.Issuer != null)
372378
{
373-
if (payload.ContainsKey(JwtRegisteredClaimNames.Iss))
379+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iss))
374380
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Issuer))));
375381

376382
payload[JwtRegisteredClaimNames.Iss] = tokenDescriptor.Issuer;
377383
}
378384

379385
if (tokenDescriptor.IssuedAt.HasValue)
380386
{
381-
if (payload.ContainsKey(JwtRegisteredClaimNames.Iat))
387+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iat))
382388
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.IssuedAt))));
383389

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

387393
if (tokenDescriptor.NotBefore.HasValue)
388394
{
389-
if (payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
395+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
390396
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.NotBefore))));
391397

392398
payload[JwtRegisteredClaimNames.Nbf] = EpochTime.GetIntDate(tokenDescriptor.NotBefore.Value);
@@ -698,7 +704,8 @@ private string CreateTokenPrivate(
698704
}
699705
catch(Exception ex)
700706
{
701-
LogHelper.LogExceptionMessage(new SecurityTokenException(LogMessages.IDX14307, ex));
707+
if (LogHelper.IsEnabled(EventLogLevel.Error))
708+
LogHelper.LogExceptionMessage(new SecurityTokenException(LogHelper.FormatInvariant(LogMessages.IDX14307, ex, payload)));
702709
}
703710

704711
payload = jsonPayload != null ? jsonPayload.ToString(Formatting.None) : payload;
@@ -841,7 +848,9 @@ private static string GetActualIssuer(JsonWebToken jwtToken)
841848
string actualIssuer = jwtToken.Issuer;
842849
if (string.IsNullOrWhiteSpace(actualIssuer))
843850
{
844-
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);
851+
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
852+
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);
853+
845854
actualIssuer = ClaimsIdentity.DefaultIssuer;
846855
}
847856

@@ -1136,12 +1145,13 @@ internal IEnumerable<SecurityKey> GetContentEncryptionKeys(JsonWebToken jwtToken
11361145
var key = ResolveTokenDecryptionKey(jwtToken.EncodedToken, jwtToken, validationParameters);
11371146
if (key != null)
11381147
{
1139-
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
1148+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1149+
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
11401150
}
11411151
else if (configuration != null)
11421152
{
11431153
key = ResolveTokenDecryptionKeyFromConfig(jwtToken, configuration);
1144-
if ( key != null )
1154+
if (key != null && LogHelper.IsEnabled(EventLogLevel.Informational))
11451155
LogHelper.LogInformation(TokenLogMessages.IDX10905, key);
11461156
}
11471157

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

@@ -1740,7 +1751,9 @@ private static JsonWebToken ValidateSignature(JsonWebToken jwtToken, TokenValida
17401751
{
17411752
if (ValidateSignature(jwtToken, key, validationParameters))
17421753
{
1743-
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);
1754+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1755+
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);
1756+
17441757
jwtToken.SigningKey = key;
17451758
return jwtToken;
17461759
}
@@ -1823,7 +1836,9 @@ internal static bool ValidateSignature(byte[] encodedBytes, byte[] signature, Se
18231836
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
18241837
if (!cryptoProviderFactory.IsSupportedAlgorithm(algorithm, key))
18251838
{
1826-
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);
1839+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1840+
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);
1841+
18271842
return false;
18281843
}
18291844

@@ -1881,7 +1896,9 @@ internal static bool ValidateSignature(JsonWebToken jsonWebToken, SecurityKey ke
18811896
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
18821897
if (!cryptoProviderFactory.IsSupportedAlgorithm(jsonWebToken.Alg, key))
18831898
{
1884-
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);
1899+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1900+
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);
1901+
18851902
return false;
18861903
}
18871904

‎src/Microsoft.IdentityModel.JsonWebTokens/JwtTokenUtilities.cs

+13-4
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
using System.Text;
1111
using System.Text.Json;
1212
using System.Text.RegularExpressions;
13+
using Microsoft.IdentityModel.Abstractions;
1314
using Microsoft.IdentityModel.Logging;
1415
using Microsoft.IdentityModel.Tokens;
1516
using Newtonsoft.Json.Linq;
@@ -97,7 +98,9 @@ public static string CreateEncodedSignature(string input, SigningCredentials sig
9798

9899
try
99100
{
100-
LogHelper.LogVerbose(LogHelper.FormatInvariant(LogMessages.IDX14201, LogHelper.MarkAsNonPII(cacheProvider)));
101+
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
102+
LogHelper.LogVerbose(LogHelper.FormatInvariant(LogMessages.IDX14201, LogHelper.MarkAsNonPII(cacheProvider)));
103+
101104
return Base64UrlEncoder.Encode(signatureProvider.Sign(Encoding.UTF8.GetBytes(input)));
102105
}
103106
finally
@@ -165,7 +168,9 @@ internal static string DecryptJwtToken(
165168
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
166169
if (cryptoProviderFactory == null)
167170
{
168-
LogHelper.LogWarning(TokenLogMessages.IDX10607, key);
171+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
172+
LogHelper.LogWarning(TokenLogMessages.IDX10607, key);
173+
169174
continue;
170175
}
171176

@@ -179,8 +184,10 @@ internal static string DecryptJwtToken(
179184
{
180185
if (!cryptoProviderFactory.IsSupportedAlgorithm(jsonWebToken.Enc, key))
181186
{
187+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
188+
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
189+
182190
algorithmNotSupportedByCryptoProvider = true;
183-
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
184191
continue;
185192
}
186193

@@ -203,8 +210,10 @@ internal static string DecryptJwtToken(
203210
{
204211
if (!cryptoProviderFactory.IsSupportedAlgorithm(decryptionParameters.Enc, key))
205212
{
213+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
214+
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
215+
206216
algorithmNotSupportedByCryptoProvider = true;
207-
LogHelper.LogWarning(TokenLogMessages.IDX10611, LogHelper.MarkAsNonPII(decryptionParameters.Enc), key);
208217
continue;
209218
}
210219

‎src/Microsoft.IdentityModel.Logging/LogHelper.cs

+19-7
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,15 @@ internal static bool HeaderWritten
4242
set { _isHeaderWritten = value; }
4343
}
4444

45+
/// <summary>
46+
/// Gets whether logging is enabled at the specified <see cref="EventLogLevel"/>."/>
47+
/// </summary>
48+
/// <param name="level">The log level</param>
49+
/// <returns><see langword="true"/> if logging is enabled at the specified level; otherwise, <see langword="false"/>.</returns>
50+
public static bool IsEnabled(EventLogLevel level) =>
51+
Logger.IsEnabled(level) ||
52+
IdentityModelEventSource.Logger.IsEnabled(EventLogLevelToEventLevel(level), EventKeywords.All);
53+
4554
/// <summary>
4655
/// Logs an exception using the event source logger and returns new <see cref="ArgumentNullException"/> exception.
4756
/// </summary>
@@ -255,7 +264,7 @@ public static Exception LogExceptionMessage(EventLevel eventLevel, Exception exc
255264
if (exception == null)
256265
return null;
257266

258-
if (IdentityModelEventSource.Logger.IsEnabled() && IdentityModelEventSource.Logger.LogLevel >= eventLevel)
267+
if (IdentityModelEventSource.Logger.IsEnabled(eventLevel, EventKeywords.All))
259268
IdentityModelEventSource.Logger.Write(eventLevel, exception.InnerException, exception.Message);
260269

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

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

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

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

326-
if (IdentityModelEventSource.Logger.IsEnabled() && IdentityModelEventSource.Logger.LogLevel >= eventLevel)
335+
if (IdentityModelEventSource.Logger.IsEnabled(eventLevel, EventKeywords.All))
327336
IdentityModelEventSource.Logger.Write(eventLevel, innerException, message);
328337

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

357+
private static EventLevel EventLogLevelToEventLevel(EventLogLevel eventLevel) =>
358+
(uint)(int)eventLevel <= 5 ? (EventLevel)eventLevel : EventLevel.Error;
359+
348360
/// <summary>
349361
/// Formats the string using InvariantCulture
350362
/// </summary>

‎src/Microsoft.IdentityModel.Logging/TextWriterEventListener.cs

+3-2
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
using System;
55
using System.Diagnostics.Tracing;
66
using System.IO;
7+
using Microsoft.IdentityModel.Abstractions;
78

89
namespace Microsoft.IdentityModel.Logging
910
{
@@ -31,7 +32,7 @@ public TextWriterEventListener()
3132
_streamWriter = new StreamWriter(fileStream);
3233
_streamWriter.AutoFlush = true;
3334
}
34-
catch (Exception ex)
35+
catch (Exception ex) when (LogHelper.IsEnabled(EventLogLevel.Error))
3536
{
3637
LogHelper.LogExceptionMessage(new InvalidOperationException(LogMessages.MIML10001, ex));
3738
throw;
@@ -53,7 +54,7 @@ public TextWriterEventListener(string filePath)
5354
_streamWriter = new StreamWriter(fileStream);
5455
_streamWriter.AutoFlush = true;
5556
}
56-
catch (Exception ex)
57+
catch (Exception ex) when (LogHelper.IsEnabled(EventLogLevel.Error))
5758
{
5859
LogHelper.LogExceptionMessage(new InvalidOperationException(LogMessages.MIML10001, ex));
5960
throw;

‎src/Microsoft.IdentityModel.Protocols.OpenIdConnect/Configuration/OpenIdConnectConfiguration.cs

+7-2
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
using System.Collections.Generic;
66
using System.Collections.ObjectModel;
77
using System.ComponentModel;
8+
using Microsoft.IdentityModel.Abstractions;
89
using Microsoft.IdentityModel.Logging;
910
using Microsoft.IdentityModel.Tokens;
1011
using Newtonsoft.Json;
@@ -31,7 +32,9 @@ public static OpenIdConnectConfiguration Create(string json)
3132
if (string.IsNullOrEmpty(json))
3233
throw LogHelper.LogArgumentNullException(nameof(json));
3334

34-
LogHelper.LogVerbose(LogMessages.IDX21808, json);
35+
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
36+
LogHelper.LogVerbose(LogMessages.IDX21808, json);
37+
3538
return new OpenIdConnectConfiguration(json);
3639
}
3740

@@ -69,7 +72,9 @@ public OpenIdConnectConfiguration(string json)
6972

7073
try
7174
{
72-
LogHelper.LogVerbose(LogMessages.IDX21806, json, LogHelper.MarkAsNonPII(_className));
75+
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
76+
LogHelper.LogVerbose(LogMessages.IDX21806, json, LogHelper.MarkAsNonPII(_className));
77+
7378
JsonConvert.PopulateObject(json, this);
7479
}
7580
catch (Exception ex)

0 commit comments

Comments
 (0)