Skip to content

Commit b48eb04

Browse files
stephentoubstephentoub
committed
Guard logging calls to avoid unnecessary work at call site
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 793d2c0 commit b48eb04

File tree

23 files changed

+255
-101
lines changed

23 files changed

+255
-101
lines changed

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

+33-16
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
using System.Text.RegularExpressions;
1111
using System.Threading;
1212
using System.Threading.Tasks;
13+
using Microsoft.IdentityModel.Abstractions;
1314
using Microsoft.IdentityModel.Json;
1415
using Microsoft.IdentityModel.Json.Linq;
1516
using Microsoft.IdentityModel.Logging;
@@ -159,7 +160,9 @@ public virtual bool CanReadToken(string token)
159160

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

@@ -327,9 +330,12 @@ public virtual string CreateToken(SecurityTokenDescriptor tokenDescriptor)
327330
if (tokenDescriptor == null)
328331
throw LogHelper.LogArgumentNullException(nameof(tokenDescriptor));
329332

330-
if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
331-
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
332-
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
333+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
334+
{
335+
if ((tokenDescriptor.Subject == null || !tokenDescriptor.Subject.Claims.Any())
336+
&& (tokenDescriptor.Claims == null || !tokenDescriptor.Claims.Any()))
337+
LogHelper.LogWarning(LogMessages.IDX14114, LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Subject)), LogHelper.MarkAsNonPII(nameof(SecurityTokenDescriptor.Claims)));
338+
}
333339

334340
JObject payload;
335341
if (tokenDescriptor.Subject != null)
@@ -344,7 +350,7 @@ public virtual string CreateToken(SecurityTokenDescriptor tokenDescriptor)
344350

345351
if (tokenDescriptor.Audience != null)
346352
{
347-
if (payload.ContainsKey(JwtRegisteredClaimNames.Aud))
353+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Aud))
348354
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Audience))));
349355

350356
payload[JwtRegisteredClaimNames.Aud] = tokenDescriptor.Audience;
@@ -360,23 +366,23 @@ public virtual string CreateToken(SecurityTokenDescriptor tokenDescriptor)
360366

361367
if (tokenDescriptor.Issuer != null)
362368
{
363-
if (payload.ContainsKey(JwtRegisteredClaimNames.Iss))
369+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iss))
364370
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.Issuer))));
365371

366372
payload[JwtRegisteredClaimNames.Iss] = tokenDescriptor.Issuer;
367373
}
368374

369375
if (tokenDescriptor.IssuedAt.HasValue)
370376
{
371-
if (payload.ContainsKey(JwtRegisteredClaimNames.Iat))
377+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Iat))
372378
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.IssuedAt))));
373379

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

377383
if (tokenDescriptor.NotBefore.HasValue)
378384
{
379-
if (payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
385+
if (LogHelper.IsEnabled(EventLogLevel.Informational) && payload.ContainsKey(JwtRegisteredClaimNames.Nbf))
380386
LogHelper.LogInformation(LogHelper.FormatInvariant(LogMessages.IDX14113, LogHelper.MarkAsNonPII(nameof(tokenDescriptor.NotBefore))));
381387

382388
payload[JwtRegisteredClaimNames.Nbf] = EpochTime.GetIntDate(tokenDescriptor.NotBefore.Value);
@@ -688,7 +694,8 @@ private string CreateTokenPrivate(
688694
}
689695
catch(Exception ex)
690696
{
691-
LogHelper.LogExceptionMessage(new SecurityTokenException(LogHelper.FormatInvariant(LogMessages.IDX14307, ex, payload)));
697+
if (LogHelper.IsEnabled(EventLogLevel.Error))
698+
LogHelper.LogExceptionMessage(new SecurityTokenException(LogHelper.FormatInvariant(LogMessages.IDX14307, ex, payload)));
692699
}
693700

694701
payload = jsonPayload != null ? jsonPayload.ToString(Formatting.None) : payload;
@@ -831,7 +838,9 @@ private static string GetActualIssuer(JsonWebToken jwtToken)
831838
string actualIssuer = jwtToken.Issuer;
832839
if (string.IsNullOrWhiteSpace(actualIssuer))
833840
{
834-
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);
841+
if (LogHelper.IsEnabled(EventLogLevel.Verbose))
842+
LogHelper.LogVerbose(TokenLogMessages.IDX10244, ClaimsIdentity.DefaultIssuer);
843+
835844
actualIssuer = ClaimsIdentity.DefaultIssuer;
836845
}
837846

@@ -1126,12 +1135,13 @@ internal IEnumerable<SecurityKey> GetContentEncryptionKeys(JsonWebToken jwtToken
11261135
var key = ResolveTokenDecryptionKey(jwtToken.EncodedToken, jwtToken, validationParameters);
11271136
if (key != null)
11281137
{
1129-
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
1138+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1139+
LogHelper.LogInformation(TokenLogMessages.IDX10904, key);
11301140
}
11311141
else if (configuration != null)
11321142
{
11331143
key = ResolveTokenDecryptionKeyFromConfig(jwtToken, configuration);
1134-
if ( key != null )
1144+
if (key != null && LogHelper.IsEnabled(EventLogLevel.Informational))
11351145
LogHelper.LogInformation(TokenLogMessages.IDX10905, key);
11361146
}
11371147

@@ -1455,7 +1465,8 @@ private async Task<TokenValidationResult> ValidateTokenAsync(JsonWebToken jsonWe
14551465
{
14561466
// The exception is not re-thrown as the TokenValidationParameters may have the issuer and signing key set
14571467
// directly on them, allowing the library to continue with token validation.
1458-
LogHelper.LogWarning(LogHelper.FormatInvariant(TokenLogMessages.IDX10261, validationParameters.ConfigurationManager.MetadataAddress, ex.ToString()));
1468+
if (LogHelper.IsEnabled(EventLogLevel.Warning))
1469+
LogHelper.LogWarning(LogHelper.FormatInvariant(TokenLogMessages.IDX10261, validationParameters.ConfigurationManager.MetadataAddress, ex.ToString()));
14591470
}
14601471
}
14611472

@@ -1731,7 +1742,9 @@ private static JsonWebToken ValidateSignature(JsonWebToken jwtToken, TokenValida
17311742
{
17321743
if (ValidateSignature(jwtToken, key, validationParameters))
17331744
{
1734-
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);
1745+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1746+
LogHelper.LogInformation(TokenLogMessages.IDX10242, jwtToken);
1747+
17351748
jwtToken.SigningKey = key;
17361749
return jwtToken;
17371750
}
@@ -1813,7 +1826,9 @@ internal static bool ValidateSignature(byte[] encodedBytes, byte[] signature, Se
18131826
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
18141827
if (!cryptoProviderFactory.IsSupportedAlgorithm(algorithm, key))
18151828
{
1816-
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);
1829+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1830+
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(algorithm), key);
1831+
18171832
return false;
18181833
}
18191834

@@ -1871,7 +1886,9 @@ internal static bool ValidateSignature(JsonWebToken jsonWebToken, SecurityKey ke
18711886
var cryptoProviderFactory = validationParameters.CryptoProviderFactory ?? key.CryptoProviderFactory;
18721887
if (!cryptoProviderFactory.IsSupportedAlgorithm(jsonWebToken.Alg, key))
18731888
{
1874-
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);
1889+
if (LogHelper.IsEnabled(EventLogLevel.Informational))
1890+
LogHelper.LogInformation(LogMessages.IDX14000, LogHelper.MarkAsNonPII(jsonWebToken.Alg), key);
1891+
18751892
return false;
18761893
}
18771894

‎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.Json.Linq;
1415
using Microsoft.IdentityModel.Logging;
1516
using Microsoft.IdentityModel.Tokens;
@@ -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)EventLevel.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.Json;
910
using Microsoft.IdentityModel.Logging;
1011
using Microsoft.IdentityModel.Tokens;
@@ -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)