From 98d6f3a121c3514a6ab8d3f9d6312b688122c73f Mon Sep 17 00:00:00 2001 From: id4s Date: Tue, 3 Jun 2025 16:56:31 -0700 Subject: [PATCH 1/2] Provide support to Log using ILogger --- .../JsonWebTokenHandler.ValidateToken.cs | 37 +- .../JsonWebTokenHandler.cs | 2 +- .../InternalAPI.Unshipped.txt | 2 + .../LogHelper.cs | 228 +++- .../LoggerContext.cs | 52 + .../Microsoft.IdentityModel.Logging.csproj | 6 +- .../PublicAPI.Unshipped.txt | 11 + .../CallContext.cs | 33 + .../TokenValidationParametersExtensions.cs | 49 + .../InternalAPI.Unshipped.txt | 1 + .../Properties/AssemblyInfo.cs | 1 + .../PublicAPI.Unshipped.txt | 5 + .../TokenHandler.cs | 5 +- .../ValidatorUtilities.cs | 55 +- .../Validators.cs | 115 +- .../ILoggerTests.cs | 1103 +++++++++++++++++ .../PIITests.cs | 10 + .../TestLogger.cs | 5 +- 18 files changed, 1656 insertions(+), 64 deletions(-) create mode 100644 src/Microsoft.IdentityModel.Tokens/Extrensions/TokenValidationParametersExtensions.cs create mode 100644 test/Microsoft.IdentityModel.Logging.Tests/ILoggerTests.cs diff --git a/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.ValidateToken.cs b/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.ValidateToken.cs index 10c1b10e6f..be6c8a0a71 100644 --- a/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.ValidateToken.cs +++ b/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.ValidateToken.cs @@ -9,8 +9,8 @@ using System.Threading.Tasks; using Microsoft.IdentityModel.Abstractions; using Microsoft.IdentityModel.Logging; -using Microsoft.IdentityModel.Tokens; using Microsoft.IdentityModel.Telemetry; +using Microsoft.IdentityModel.Tokens; using TokenLogMessages = Microsoft.IdentityModel.Tokens.LogMessages; namespace Microsoft.IdentityModel.JsonWebTokens @@ -444,14 +444,36 @@ public override async Task ValidateTokenAsync(string toke public override async Task ValidateTokenAsync(SecurityToken token, TokenValidationParameters validationParameters) { if (token == null) - throw LogHelper.LogArgumentNullException(nameof(token)); + { + return new TokenValidationResult + { + Exception = LogHelper.LogArgumentNullException(nameof(token)), + IsValid = false + }; + } if (validationParameters == null) - return new TokenValidationResult { Exception = LogHelper.LogArgumentNullException(nameof(validationParameters)), IsValid = false }; + return new TokenValidationResult + { + Exception = LogHelper.LogArgumentNullException(nameof(validationParameters)), + IsValid = false + }; var jwt = token as JsonWebToken; if (jwt == null) - return new TokenValidationResult { Exception = LogHelper.LogArgumentException(nameof(token), $"{nameof(token)} must be a {nameof(JsonWebToken)}."), IsValid = false }; + { + return new TokenValidationResult + { + Exception = LogHelper.LogExceptionMessage( + new ArgumentException( + $"{nameof(token)} must be a {nameof(JsonWebToken)}.", + nameof(token) + ), + TokenValidationParametersExtensions.GetCallContext(validationParameters) + ), + IsValid = false + }; + } try { @@ -480,6 +502,7 @@ internal async ValueTask ValidateTokenAsync( TokenValidationParameters validationParameters) { BaseConfiguration currentConfiguration = null; + if (validationParameters.ConfigurationManager != null) { try @@ -493,7 +516,11 @@ internal async ValueTask ValidateTokenAsync( // 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. if (LogHelper.IsEnabled(EventLogLevel.Warning)) - LogHelper.LogWarning(LogHelper.FormatInvariant(TokenLogMessages.IDX10261, validationParameters.ConfigurationManager.MetadataAddress, ex.ToString())); + LogHelper.LogWarning( + LogHelper.FormatInvariant( + TokenLogMessages.IDX10261, + validationParameters.ConfigurationManager.MetadataAddress, + ex.ToString())); } } diff --git a/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs b/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs index 2a722a0cbd..e42fb0c560 100644 --- a/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs +++ b/src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs @@ -15,7 +15,7 @@ namespace Microsoft.IdentityModel.JsonWebTokens { /// - /// A designed for creating and validating JSON Web Tokens. + /// A designed for creating and validating JSON Web Tokens. /// See: and . /// public partial class JsonWebTokenHandler : TokenHandler diff --git a/src/Microsoft.IdentityModel.Logging/InternalAPI.Unshipped.txt b/src/Microsoft.IdentityModel.Logging/InternalAPI.Unshipped.txt index e69de29bb2..58b7242a76 100644 --- a/src/Microsoft.IdentityModel.Logging/InternalAPI.Unshipped.txt +++ b/src/Microsoft.IdentityModel.Logging/InternalAPI.Unshipped.txt @@ -0,0 +1,2 @@ +static Microsoft.IdentityModel.Logging.LogHelper.IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.IdentityModel.Logging.LoggerContext loggerContext) -> bool +static Microsoft.IdentityModel.Logging.LogHelper.IsEnabled(Microsoft.IdentityModel.Abstractions.EventLogLevel level, Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.IdentityModel.Logging.LoggerContext loggerContext) -> bool \ No newline at end of file diff --git a/src/Microsoft.IdentityModel.Logging/LogHelper.cs b/src/Microsoft.IdentityModel.Logging/LogHelper.cs index b2282954fc..a91c299e36 100644 --- a/src/Microsoft.IdentityModel.Logging/LogHelper.cs +++ b/src/Microsoft.IdentityModel.Logging/LogHelper.cs @@ -6,6 +6,7 @@ using System.Diagnostics.Tracing; using System.Globalization; using System.Linq; +using Microsoft.Extensions.Logging; using Microsoft.IdentityModel.Abstractions; namespace Microsoft.IdentityModel.Logging @@ -42,6 +43,17 @@ internal static bool HeaderWritten set { _isHeaderWritten = value; } } + /// + /// Gets a boolean indicating whether logging is enabled at the specified LogLevel. + /// + /// The log level + /// A that contains logging control including . + /// if logging is enabled at the specified level; otherwise, . + internal static bool IsEnabled(LogLevel logLevel, LoggerContext loggerContext) + { + return loggerContext?.Logger?.IsEnabled(logLevel) ?? false; + } + /// /// Gets whether logging is enabled at the specified ."/> /// @@ -269,7 +281,38 @@ public static Exception LogExceptionMessage(EventLevel eventLevel, Exception exc EventLogLevel eventLogLevel = EventLevelToEventLogLevel(eventLevel); if (Logger.IsEnabled(eventLogLevel)) - Logger.Log(WriteEntry(eventLogLevel, exception.InnerException, exception.Message, null)); + Logger.Log(WriteEntry(eventLogLevel, exception.InnerException, exception.Message)); + + return exception; + } + + /// + /// Logs an exception using the listeners that have been enabled. + /// + /// The exception to log. + /// The contains information useful for logging and debugging. + public static Exception LogExceptionMessage(Exception exception, LoggerContext loggerContext) + { + if (exception == null) + return null; + + LogExceptionMessage(exception); + + if (loggerContext?.Logger == null) + return exception; + + if (!loggerContext.Logger.IsEnabled(LogLevel.Error)) + return exception; + + LogEntry entry = WriteEntry( + EventLogLevel.Error, + exception.InnerException, + exception.Message, + loggerContext.CorrelationId ?? loggerContext.ActivityId.ToString(), + exception.Message, + null); + + Log(entry, loggerContext.Logger); return exception; } @@ -285,7 +328,33 @@ public static void LogInformation(string message, params object[] args) IdentityModelEventSource.Logger.WriteInformation(message, args); if (Logger.IsEnabled(EventLogLevel.Informational)) - Logger.Log(WriteEntry(EventLogLevel.Informational, null, message, args)); + Logger.Log(WriteEntry(EventLogLevel.Informational, null, message, null, args)); + } + + /// + /// Logs at the information level to the listeners that have been enabled. + /// + /// The log message. + /// A that contains logging control including . + /// An object array that contains zero or more objects to format. + public static void LogInformation(string message, LoggerContext loggerContext, params object[] args) + { + LogInformation(message, args); + + if (loggerContext?.Logger == null) + return; + + if (!loggerContext.Logger.IsEnabled(LogLevel.Information)) + return; + + LogEntry entry = WriteEntry( + EventLevelToEventLogLevel(EventLevel.Informational), + null, + message, + loggerContext.CorrelationId ?? loggerContext.ActivityId.ToString(), + null); + + Log(entry, loggerContext.Logger); } /// @@ -299,7 +368,33 @@ public static void LogVerbose(string message, params object[] args) IdentityModelEventSource.Logger.WriteVerbose(message, args); if (Logger.IsEnabled(EventLogLevel.Verbose)) - Logger.Log(WriteEntry(EventLogLevel.Verbose, null, message, args)); + Logger.Log(WriteEntry(EventLogLevel.Verbose, null, message, null, args)); + } + + /// + /// Logs at the verbose level to the listeners that have been enabled. + /// + /// The log message. + /// A that contains logging control including . + /// An object array that contains zero or more objects to format. + public static void LogVerbose(string message, LoggerContext loggerContext, params object[] args) + { + LogVerbose(message, args); + + if (loggerContext?.Logger == null) + return; + + if (!loggerContext.Logger.IsEnabled(LogLevel.Debug)) + return; + + LogEntry entry = WriteEntry( + EventLogLevel.Verbose, + null, + message, + loggerContext.CorrelationId ?? loggerContext.ActivityId.ToString(), + null); + + Log(entry, loggerContext.Logger); } /// @@ -313,7 +408,43 @@ public static void LogWarning(string message, params object[] args) IdentityModelEventSource.Logger.WriteWarning(message, args); if (Logger.IsEnabled(EventLogLevel.Warning)) - Logger.Log(WriteEntry(EventLogLevel.Warning, null, message, args)); + Logger.Log(WriteEntry(EventLogLevel.Warning, null, message, null, args)); + } + + /// + /// Logs at the warning level to the listeners that have been enabled. + /// + /// The log message. + /// A that contains logging control including . + public static void LogWarning(string message, LoggerContext loggerContext) + { + LogWarning(message, loggerContext, null); + } + + /// + /// Logs at the warning level to the listeners that have been enabled. + /// + /// The log message. + /// A that contains logging control including . + /// An object array that contains zero or more objects to format. + public static void LogWarning(string message, LoggerContext loggerContext, params object[] args) + { + LogWarning(message, args); + + if (loggerContext?.Logger == null) + return; + + if (!loggerContext.Logger.IsEnabled(LogLevel.Warning)) + return; + + LogEntry entry = WriteEntry( + EventLogLevel.Warning, + null, + message, + loggerContext.CorrelationId ?? loggerContext.ActivityId.ToString(), + null); + + Log(entry, loggerContext.Logger); } /// @@ -337,7 +468,7 @@ public static void LogWarning(string message, params object[] args) EventLogLevel eventLogLevel = EventLevelToEventLogLevel(eventLevel); if (Logger.IsEnabled(eventLogLevel)) - Logger.Log(WriteEntry(eventLogLevel, innerException, message, null)); + Logger.Log(WriteEntry(eventLogLevel, innerException, message)); if (innerException != null) { @@ -487,7 +618,29 @@ public static object MarkAsUnsafeSecurityArtifact(object arg, Func /// The log message. /// An object array that contains zero or more objects to format. - private static LogEntry WriteEntry(EventLogLevel eventLogLevel, Exception innerException, string message, params object[] args) + private static LogEntry WriteEntry( + EventLogLevel eventLogLevel, + Exception innerException, + string message, + params object[] args) + { + return WriteEntry(eventLogLevel, innerException, message, (string)null, args); + } + + /// + /// Creates a by using the provided event level, exception argument, string argument and arguments list. + /// + /// + /// + /// The log message. + /// The CorrelationId is set by caller to coordinate logs between services. + /// An object array that contains zero or more objects to format. + private static LogEntry WriteEntry( + EventLogLevel eventLogLevel, + Exception innerException, + string message, + string correlationId, + params object[] args) { if (string.IsNullOrEmpty(message)) return null; @@ -505,23 +658,72 @@ private static LogEntry WriteEntry(EventLogLevel eventLogLevel, Exception innerE LogEntry entry = new LogEntry(); entry.EventLogLevel = eventLogLevel; + entry.CorrelationId = correlationId; // Prefix header (library version, DateTime, whether PII is ON/OFF) to the first message logged by Wilson. if (!_isHeaderWritten) { - string headerMessage = string.Format(CultureInfo.InvariantCulture, "Microsoft.IdentityModel Version: {0}. Date {1}. {2}", - typeof(IdentityModelEventSource).Assembly.GetName().Version.ToString(), - DateTime.UtcNow, - IdentityModelEventSource.ShowPII ? _piiOnLogMessage : _piiOffLogMessage); - - entry.Message = headerMessage + Environment.NewLine + message; + entry.Message = (correlationId == null) ? + string.Format( + CultureInfo.InvariantCulture, + "Microsoft.IdentityModel Version: {0}. Date {1}. {2} Message: {3}", + typeof(IdentityModelEventSource).Assembly.GetName().Version.ToString(), + DateTime.UtcNow, + IdentityModelEventSource.ShowPII ? _piiOnLogMessage : _piiOffLogMessage, + Environment.NewLine + message) : + string.Format( + CultureInfo.InvariantCulture, + "Microsoft.IdentityModel Version: {0}. Date {1}. {2} Message: {3}, CorrelationId: {4}.", + typeof(IdentityModelEventSource).Assembly.GetName().Version.ToString(), + DateTime.UtcNow, + IdentityModelEventSource.ShowPII ? _piiOnLogMessage : _piiOffLogMessage, + Environment.NewLine + message, + correlationId); _isHeaderWritten = true; } else - entry.Message = message; + entry.Message = (correlationId == null) ? + message : + string.Format(CultureInfo.InvariantCulture, "{0}, CorrelationId: {1}.", message, correlationId); return entry; } + + private static void Log(LogEntry entry, ILogger logger) + { + if (entry != null) + { + switch (entry.EventLogLevel) + { + case EventLogLevel.Critical: + logger.LogCritical(entry.Message); + break; + + case EventLogLevel.Error: + logger.LogError(entry.Message); + break; + + case EventLogLevel.Warning: + logger.LogWarning(entry.Message); + break; + + case EventLogLevel.Informational: + logger.LogInformation(entry.Message); + break; + + case EventLogLevel.Verbose: + logger.LogDebug(entry.Message); + break; + + case EventLogLevel.LogAlways: + logger.LogTrace(entry.Message); + break; + + default: + break; + } + } + } } } diff --git a/src/Microsoft.IdentityModel.Logging/LoggerContext.cs b/src/Microsoft.IdentityModel.Logging/LoggerContext.cs index a6adc5554f..d848392db4 100644 --- a/src/Microsoft.IdentityModel.Logging/LoggerContext.cs +++ b/src/Microsoft.IdentityModel.Logging/LoggerContext.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Collections.ObjectModel; +using Microsoft.Extensions.Logging; namespace Microsoft.IdentityModel.Logging { @@ -28,9 +29,60 @@ public LoggerContext(Guid activityId) ActivityId = activityId; } +#pragma warning disable CS3001 // ILogger is not CLSCompliant +#pragma warning disable CS3003 // ILogger is not CLSCompliant + /// + /// Instantiates a new . + /// + /// to record logs. + /// if is null. + public LoggerContext(ILogger logger) + { + Logger = logger ?? throw new ArgumentNullException(nameof(logger)); + } + + /// + /// Instantiates a new with an activity identifier. + /// + /// to record logs. + /// activity id to include in logs. + /// if is null. + public LoggerContext(ILogger logger, Guid activityId) + { + Logger = logger ?? throw new ArgumentNullException(nameof(logger)); + ActivityId = activityId; + } + + /// + /// Instantiates a new with a correlation identifier. + /// + /// to record logs. + /// correlation id to include in logs. + /// if is null. + public LoggerContext(ILogger logger, string correlationId) + { + Logger = logger ?? throw new ArgumentNullException(nameof(logger)); + CorrelationId = correlationId; + } + + /// + /// Gets the that will be used to log messages. + /// + public ILogger Logger { get; } + +#pragma warning restore CS3001 // ILogger is not CLSCompliant +#pragma warning restore CS3003 // ILogger is not CLSCompliant + + /// + /// Gets or set a that will be logged. + /// + /// will take precedence over when logging using ILogger. + public string CorrelationId { get; set; } + /// /// Gets or set a that will be used in the call to EventSource.SetCurrentThreadActivityId before logging. /// + /// will take precedence over when logging using ILogger. public Guid ActivityId { get; set; } = Guid.Empty; /// diff --git a/src/Microsoft.IdentityModel.Logging/Microsoft.IdentityModel.Logging.csproj b/src/Microsoft.IdentityModel.Logging/Microsoft.IdentityModel.Logging.csproj index e6a1110b05..3c1dcfc1d7 100644 --- a/src/Microsoft.IdentityModel.Logging/Microsoft.IdentityModel.Logging.csproj +++ b/src/Microsoft.IdentityModel.Logging/Microsoft.IdentityModel.Logging.csproj @@ -1,4 +1,4 @@ - + @@ -36,6 +36,10 @@ + + + + diff --git a/src/Microsoft.IdentityModel.Logging/PublicAPI.Unshipped.txt b/src/Microsoft.IdentityModel.Logging/PublicAPI.Unshipped.txt index e69de29bb2..dca4771991 100644 --- a/src/Microsoft.IdentityModel.Logging/PublicAPI.Unshipped.txt +++ b/src/Microsoft.IdentityModel.Logging/PublicAPI.Unshipped.txt @@ -0,0 +1,11 @@ +Microsoft.IdentityModel.Logging.LoggerContext.CorrelationId.get -> string +Microsoft.IdentityModel.Logging.LoggerContext.CorrelationId.set -> void +Microsoft.IdentityModel.Logging.LoggerContext.Logger.get -> Microsoft.Extensions.Logging.ILogger +Microsoft.IdentityModel.Logging.LoggerContext.LoggerContext(Microsoft.Extensions.Logging.ILogger logger) -> void +Microsoft.IdentityModel.Logging.LoggerContext.LoggerContext(Microsoft.Extensions.Logging.ILogger logger, string correlationId) -> void +Microsoft.IdentityModel.Logging.LoggerContext.LoggerContext(Microsoft.Extensions.Logging.ILogger logger, System.Guid activityId) -> void +static Microsoft.IdentityModel.Logging.LogHelper.LogExceptionMessage(System.Exception exception, Microsoft.IdentityModel.Logging.LoggerContext loggerContext) -> System.Exception +static Microsoft.IdentityModel.Logging.LogHelper.LogInformation(string message, Microsoft.IdentityModel.Logging.LoggerContext loggerContext, params object[] args) -> void +static Microsoft.IdentityModel.Logging.LogHelper.LogVerbose(string message, Microsoft.IdentityModel.Logging.LoggerContext loggerContext, params object[] args) -> void +static Microsoft.IdentityModel.Logging.LogHelper.LogWarning(string message, Microsoft.IdentityModel.Logging.LoggerContext loggerContext) -> void +static Microsoft.IdentityModel.Logging.LogHelper.LogWarning(string message, Microsoft.IdentityModel.Logging.LoggerContext loggerContext, params object[] args) -> void \ No newline at end of file diff --git a/src/Microsoft.IdentityModel.Tokens/CallContext.cs b/src/Microsoft.IdentityModel.Tokens/CallContext.cs index 5b4a8b6d7a..eea2888501 100644 --- a/src/Microsoft.IdentityModel.Tokens/CallContext.cs +++ b/src/Microsoft.IdentityModel.Tokens/CallContext.cs @@ -2,6 +2,7 @@ // Licensed under the MIT License. using System; +using Microsoft.Extensions.Logging; using Microsoft.IdentityModel.Logging; namespace Microsoft.IdentityModel.Tokens @@ -24,5 +25,37 @@ public CallContext() : base() public CallContext(Guid activityId) : base(activityId) { } +#pragma warning disable CS3001 // ILogger is not CLSCompliant +#pragma warning disable CS3003 // ILogger is not CLSCompliant + /// + /// Instantiates a new with an activity identifier. + /// + /// to record logs. + /// Activity Id to include in logs. + /// if is null. + public CallContext(ILogger logger, Guid activityId) : base(logger, activityId) + { + } + + /// + /// Instantiates a new with a Correlation Id. + /// + /// to record logs. + /// Correlation Id to include in logs. + /// if is null. + public CallContext(ILogger logger, string correlationId) : base(logger, correlationId) + { + } + + /// + /// Instantiates a new with a logger. + /// + /// to record logs. + /// if is null. + public CallContext(ILogger logger) : base(logger) + { + } +#pragma warning restore CS3001 // ILogger is not CLSCompliant +#pragma warning restore CS3003 // ILogger is not CLSCompliant } } diff --git a/src/Microsoft.IdentityModel.Tokens/Extrensions/TokenValidationParametersExtensions.cs b/src/Microsoft.IdentityModel.Tokens/Extrensions/TokenValidationParametersExtensions.cs new file mode 100644 index 0000000000..cdb46a0224 --- /dev/null +++ b/src/Microsoft.IdentityModel.Tokens/Extrensions/TokenValidationParametersExtensions.cs @@ -0,0 +1,49 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System; +using Microsoft.Extensions.Logging; + +namespace Microsoft.IdentityModel.Tokens +{ + /// + /// Extensions for . + /// + [CLSCompliant(false)] + public static class TokenValidationParametersExtensions + { + internal static string s_callContextKey = typeof(TokenValidationParameters).FullName + ".CallContext"; + + /// + /// Adds the provided to the . + /// + /// The instance. + /// The to use. + public static void SetLogger(this TokenValidationParameters validationParameters, ILogger logger) + { + if (validationParameters == null) + throw new ArgumentNullException(nameof(validationParameters)); + + if (logger == null) + throw new ArgumentNullException(nameof(logger)); + + validationParameters.InstancePropertyBag[s_callContextKey] = new CallContext(logger); + } + + /// + /// Retrieves the from . + /// + /// + /// A + internal static CallContext GetCallContext(this TokenValidationParameters validationParameters) + { + if (validationParameters == null) + return null; + + if (validationParameters.InstancePropertyBag.TryGetValue(s_callContextKey, out var obj) && obj is CallContext callContext) + return callContext; + + return null; + } + } +} diff --git a/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt b/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt index 4194681d26..0b7df241c2 100644 --- a/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt +++ b/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt @@ -110,3 +110,4 @@ virtual Microsoft.IdentityModel.Tokens.TokenHandler.CreateClaimsIdentityInternal virtual Microsoft.IdentityModel.Tokens.TokenHandler.ValidateTokenAsync(Microsoft.IdentityModel.Tokens.SecurityToken token, Microsoft.IdentityModel.Tokens.Experimental.ValidationParameters validationParameters, Microsoft.IdentityModel.Tokens.CallContext callContext, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task> virtual Microsoft.IdentityModel.Tokens.TokenHandler.ValidateTokenAsync(string token, Microsoft.IdentityModel.Tokens.Experimental.ValidationParameters validationParameters, Microsoft.IdentityModel.Tokens.CallContext callContext, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task> virtual Microsoft.IdentityModel.Tokens.ValidationError.CreateException() -> System.Exception +static Microsoft.IdentityModel.Tokens.TokenValidationParametersExtensions.GetCallContext(this Microsoft.IdentityModel.Tokens.TokenValidationParameters parameters) -> Microsoft.IdentityModel.Tokens.CallContext diff --git a/src/Microsoft.IdentityModel.Tokens/Properties/AssemblyInfo.cs b/src/Microsoft.IdentityModel.Tokens/Properties/AssemblyInfo.cs index 12d7bcb55f..7a8140fc3f 100644 --- a/src/Microsoft.IdentityModel.Tokens/Properties/AssemblyInfo.cs +++ b/src/Microsoft.IdentityModel.Tokens/Properties/AssemblyInfo.cs @@ -30,3 +30,4 @@ [assembly: InternalsVisibleTo("Microsoft.IdentityModel.S2S.Tokens, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")] [assembly: InternalsVisibleTo("Microsoft.IdentityModel.S2S.Tokens.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")] [assembly: InternalsVisibleTo("System.IdentityModel.Tokens.Jwt, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")] +[assembly: InternalsVisibleTo("Microsoft.IdentityModel.Logging.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")] diff --git a/src/Microsoft.IdentityModel.Tokens/PublicAPI.Unshipped.txt b/src/Microsoft.IdentityModel.Tokens/PublicAPI.Unshipped.txt index 55cad57736..81f2adfdf9 100644 --- a/src/Microsoft.IdentityModel.Tokens/PublicAPI.Unshipped.txt +++ b/src/Microsoft.IdentityModel.Tokens/PublicAPI.Unshipped.txt @@ -307,3 +307,8 @@ virtual Microsoft.IdentityModel.Tokens.Experimental.ValidationParameters.CreateC ~static Microsoft.IdentityModel.Tokens.Experimental.MessageDetail.NullParameter(string parameterName) -> Microsoft.IdentityModel.Tokens.Experimental.MessageDetail Microsoft.IdentityModel.Tokens.JsonWebKeySet.JsonData.get -> string Microsoft.IdentityModel.Tokens.JsonWebKeySet.JsonData.set -> void +Microsoft.IdentityModel.Tokens.TokenValidationParametersExtensions +static Microsoft.IdentityModel.Tokens.TokenValidationParametersExtensions.SetLogger(this Microsoft.IdentityModel.Tokens.TokenValidationParameters validationParameters, Microsoft.Extensions.Logging.ILogger logger) -> void +~Microsoft.IdentityModel.Tokens.CallContext.CallContext(Microsoft.Extensions.Logging.ILogger logger) -> void +~Microsoft.IdentityModel.Tokens.CallContext.CallContext(Microsoft.Extensions.Logging.ILogger logger, System.Guid activityId) -> void +~Microsoft.IdentityModel.Tokens.CallContext.CallContext(Microsoft.Extensions.Logging.ILogger logger, string correlationId) -> void diff --git a/src/Microsoft.IdentityModel.Tokens/TokenHandler.cs b/src/Microsoft.IdentityModel.Tokens/TokenHandler.cs index c293f930ac..426b35e3dd 100644 --- a/src/Microsoft.IdentityModel.Tokens/TokenHandler.cs +++ b/src/Microsoft.IdentityModel.Tokens/TokenHandler.cs @@ -53,6 +53,7 @@ public int TokenLifetimeInMinutes } #region methods + /// /// Validates a token. /// On a validation failure, no exception will be thrown; instead, the exception will be set in the returned TokenValidationResult.Exception property. @@ -79,7 +80,9 @@ public virtual Task ValidateTokenAsync(string token, Toke /// The to be validated. /// The to be used for validating the token. /// A - public virtual Task ValidateTokenAsync(SecurityToken token, TokenValidationParameters validationParameters) + public virtual Task ValidateTokenAsync( + SecurityToken token, + TokenValidationParameters validationParameters) { throw LogExceptionMessage( new NotImplementedException( diff --git a/src/Microsoft.IdentityModel.Tokens/ValidatorUtilities.cs b/src/Microsoft.IdentityModel.Tokens/ValidatorUtilities.cs index 5aae796ee7..d65d7efe90 100644 --- a/src/Microsoft.IdentityModel.Tokens/ValidatorUtilities.cs +++ b/src/Microsoft.IdentityModel.Tokens/ValidatorUtilities.cs @@ -26,32 +26,57 @@ internal static class ValidatorUtilities /// All time comparisons apply . internal static void ValidateLifetime(DateTime? notBefore, DateTime? expires, SecurityToken securityToken, TokenValidationParameters validationParameters) { + CallContext callContext = validationParameters.GetCallContext(); if (!expires.HasValue && validationParameters.RequireExpirationTime) - throw LogHelper.LogExceptionMessage(new SecurityTokenNoExpirationException(LogHelper.FormatInvariant(LogMessages.IDX10225, LogHelper.MarkAsNonPII(securityToken == null ? "null" : securityToken.GetType().ToString())))); + throw LogHelper.LogExceptionMessage( + new SecurityTokenNoExpirationException( + LogHelper.FormatInvariant( + LogMessages.IDX10225, + LogHelper.MarkAsNonPII(securityToken == null ? "null" : securityToken.GetType().ToString()))), + callContext); if (notBefore.HasValue && expires.HasValue && (notBefore.Value > expires.Value)) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidLifetimeException(LogHelper.FormatInvariant(LogMessages.IDX10224, LogHelper.MarkAsNonPII(notBefore.Value), LogHelper.MarkAsNonPII(expires.Value))) - { - NotBefore = notBefore, - Expires = expires - }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidLifetimeException( + LogHelper.FormatInvariant( + LogMessages.IDX10224, + LogHelper.MarkAsNonPII(notBefore.Value), + LogHelper.MarkAsNonPII(expires.Value))) + { + NotBefore = notBefore, + Expires = expires + }, + callContext); DateTime utcNow = validationParameters.TimeProvider.GetUtcNow().UtcDateTime; if (notBefore.HasValue && (notBefore.Value > DateTimeUtil.Add(utcNow, validationParameters.ClockSkew))) - throw LogHelper.LogExceptionMessage(new SecurityTokenNotYetValidException(LogHelper.FormatInvariant(LogMessages.IDX10222, LogHelper.MarkAsNonPII(notBefore.Value), LogHelper.MarkAsNonPII(utcNow))) - { - NotBefore = notBefore.Value - }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenNotYetValidException( + LogHelper.FormatInvariant( + LogMessages.IDX10222, + LogHelper.MarkAsNonPII(notBefore.Value), + LogHelper.MarkAsNonPII(utcNow))) + { + NotBefore = notBefore.Value + }, + callContext); if (expires.HasValue && (expires.Value < DateTimeUtil.Add(utcNow, validationParameters.ClockSkew.Negate()))) - throw LogHelper.LogExceptionMessage(new SecurityTokenExpiredException(LogHelper.FormatInvariant(LogMessages.IDX10223, LogHelper.MarkAsNonPII(expires.Value), LogHelper.MarkAsNonPII(utcNow))) - { - Expires = expires.Value - }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenExpiredException( + LogHelper.FormatInvariant( + LogMessages.IDX10223, + LogHelper.MarkAsNonPII(expires.Value), + LogHelper.MarkAsNonPII(utcNow))) + { + Expires = expires.Value + }, + callContext); // if it reaches here, that means lifetime of the token is valid + // TODO need to consider if ILogger is available and if so is it enabled for informational messages if (LogHelper.IsEnabled(EventLogLevel.Informational)) - LogHelper.LogInformation(LogMessages.IDX10239); + LogHelper.LogInformation(LogMessages.IDX10239, callContext); } } } diff --git a/src/Microsoft.IdentityModel.Tokens/Validators.cs b/src/Microsoft.IdentityModel.Tokens/Validators.cs index c6a52f54de..c7408a9894 100644 --- a/src/Microsoft.IdentityModel.Tokens/Validators.cs +++ b/src/Microsoft.IdentityModel.Tokens/Validators.cs @@ -6,6 +6,7 @@ using System.Linq; using System.Security.Cryptography.X509Certificates; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Microsoft.IdentityModel.Abstractions; using Microsoft.IdentityModel.Logging; @@ -61,11 +62,16 @@ public static void ValidateAlgorithm(string algorithm, SecurityKey securityKey, /// If is null or whitespace and is null. /// If none of the 'audiences' matched either or one of . /// An EXACT match is required. - public static void ValidateAudience(IEnumerable audiences, SecurityToken securityToken, TokenValidationParameters validationParameters) + public static void ValidateAudience( + IEnumerable audiences, + SecurityToken securityToken, + TokenValidationParameters validationParameters) { if (validationParameters == null) throw LogHelper.LogArgumentNullException(nameof(validationParameters)); + CallContext callContext = validationParameters.GetCallContext(); + if (validationParameters.AudienceValidator != null) { if (!validationParameters.AudienceValidator(audiences, securityToken, validationParameters)) @@ -76,33 +82,47 @@ public static void ValidateAudience(IEnumerable audiences, SecurityToken LogHelper.MarkAsUnsafeSecurityArtifact(securityToken, t => t.ToString()))) { InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences) - }); + }, + callContext); return; } if (!validationParameters.ValidateAudience) { - LogHelper.LogWarning(LogMessages.IDX10233); + LogHelper.LogWarning(LogMessages.IDX10233, callContext); return; } if (!validationParameters.RequireAudience && !audiences.Any()) { - LogHelper.LogWarning(LogMessages.IDX10277); + LogHelper.LogWarning(LogMessages.IDX10277, callContext); return; } if (audiences == null) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidAudienceException(LogMessages.IDX10207) { InvalidAudience = null }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidAudienceException(LogMessages.IDX10207) + { + InvalidAudience = null + }, + callContext); if (string.IsNullOrWhiteSpace(validationParameters.ValidAudience) && (validationParameters.ValidAudiences == null)) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidAudienceException(LogMessages.IDX10208) { InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences) }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidAudienceException(LogMessages.IDX10208) + { + InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences) + }, + callContext); if (!audiences.Any()) throw LogHelper.LogExceptionMessage( new SecurityTokenInvalidAudienceException(LogHelper.FormatInvariant(LogMessages.IDX10206)) - { InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences) }); + { + InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences) + }, + callContext); // create enumeration of all valid audiences from validationParameters IEnumerable validationParametersAudiences; @@ -133,7 +153,9 @@ public static void ValidateAudience(IEnumerable audiences, SecurityToken if (!validationParameters.LogValidationExceptions) throw ex; - throw LogHelper.LogExceptionMessage(ex); + throw LogHelper.LogExceptionMessage( + ex, + callContext); } private static bool AudienceIsValid(IEnumerable audiences, TokenValidationParameters validationParameters, IEnumerable validationParametersAudiences) @@ -279,38 +301,61 @@ internal static async ValueTask ValidateIssuerAsync( if (validationParameters == null) throw LogHelper.LogArgumentNullException(nameof(validationParameters)); - if (validationParameters.IssuerValidatorAsync != null) - return await validationParameters.IssuerValidatorAsync(issuer, securityToken, validationParameters).ConfigureAwait(false); + CallContext callContext = validationParameters.GetCallContext(); + + try + { + if (validationParameters.IssuerValidatorAsync != null) + return await validationParameters.IssuerValidatorAsync(issuer, securityToken, validationParameters).ConfigureAwait(false); + + if (validationParameters.IssuerValidatorUsingConfiguration != null) + return validationParameters.IssuerValidatorUsingConfiguration(issuer, securityToken, validationParameters, configuration); - if (validationParameters.IssuerValidatorUsingConfiguration != null) - return validationParameters.IssuerValidatorUsingConfiguration(issuer, securityToken, validationParameters, configuration); + if (validationParameters.IssuerValidator != null) + return validationParameters.IssuerValidator(issuer, securityToken, validationParameters); + } + catch (Exception exception) + { + if (LogHelper.IsEnabled(EventLogLevel.Error) || (callContext?.Logger?.IsEnabled(LogLevel.Error) ?? false)) + LogHelper.LogExceptionMessage(exception, callContext); - if (validationParameters.IssuerValidator != null) - return validationParameters.IssuerValidator(issuer, securityToken, validationParameters); + throw; + } if (!validationParameters.ValidateIssuer) { - LogHelper.LogWarning(LogMessages.IDX10235); + LogHelper.LogWarning(LogMessages.IDX10235, callContext); return issuer; } if (string.IsNullOrWhiteSpace(issuer)) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidIssuerException(LogMessages.IDX10211) - { InvalidIssuer = issuer }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidIssuerException(LogMessages.IDX10211) + { + InvalidIssuer = issuer + }, + callContext); // Throw if all possible places to validate against are null or empty if (string.IsNullOrWhiteSpace(validationParameters.ValidIssuer) && validationParameters.ValidIssuers.IsNullOrEmpty() && string.IsNullOrWhiteSpace(configuration?.Issuer)) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidIssuerException(LogMessages.IDX10204) - { InvalidIssuer = issuer }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidIssuerException(LogMessages.IDX10204) + { + InvalidIssuer = issuer + }, + callContext); if (configuration != null) { if (string.Equals(configuration.Issuer, issuer)) { if (LogHelper.IsEnabled(EventLogLevel.Informational)) - LogHelper.LogInformation(LogMessages.IDX10236, LogHelper.MarkAsNonPII(issuer)); + LogHelper.LogInformation( + LogMessages.IDX10236, + callContext, + LogHelper.MarkAsNonPII(issuer)); return issuer; } @@ -319,7 +364,10 @@ internal static async ValueTask ValidateIssuerAsync( if (string.Equals(validationParameters.ValidIssuer, issuer)) { if (LogHelper.IsEnabled(EventLogLevel.Informational)) - LogHelper.LogInformation(LogMessages.IDX10236, LogHelper.MarkAsNonPII(issuer)); + LogHelper.LogInformation( + LogMessages.IDX10236, + callContext, + LogHelper.MarkAsNonPII(issuer)); return issuer; } @@ -330,14 +378,20 @@ internal static async ValueTask ValidateIssuerAsync( { if (string.IsNullOrEmpty(str)) { - LogHelper.LogInformation(LogMessages.IDX10262); + LogHelper.LogInformation( + LogMessages.IDX10262, + callContext, + null); continue; } if (string.Equals(str, issuer)) { if (LogHelper.IsEnabled(EventLogLevel.Informational)) - LogHelper.LogInformation(LogMessages.IDX10236, LogHelper.MarkAsNonPII(issuer)); + LogHelper.LogInformation( + LogMessages.IDX10236, + callContext, + LogHelper.MarkAsNonPII(issuer)); return issuer; } @@ -355,7 +409,7 @@ internal static async ValueTask ValidateIssuerAsync( if (!validationParameters.LogValidationExceptions) throw ex; - throw LogHelper.LogExceptionMessage(ex); + throw LogHelper.LogExceptionMessage(ex, callContext); } /// @@ -466,18 +520,25 @@ public static void ValidateLifetime(DateTime? notBefore, DateTime? expires, Secu if (validationParameters == null) throw LogHelper.LogArgumentNullException(nameof(validationParameters)); + CallContext callContext = validationParameters.GetCallContext(); + if (validationParameters.LifetimeValidator != null) { if (!validationParameters.LifetimeValidator(notBefore, expires, securityToken, validationParameters)) - throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidLifetimeException(LogHelper.FormatInvariant(LogMessages.IDX10230, securityToken)) - { NotBefore = notBefore, Expires = expires }); + throw LogHelper.LogExceptionMessage( + new SecurityTokenInvalidLifetimeException(LogHelper.FormatInvariant(LogMessages.IDX10230, securityToken)) + { + NotBefore = notBefore, + Expires = expires + }, + callContext); return; } if (!validationParameters.ValidateLifetime) { - LogHelper.LogInformation(LogMessages.IDX10238); + LogHelper.LogWarning(LogMessages.IDX10238, callContext); return; } diff --git a/test/Microsoft.IdentityModel.Logging.Tests/ILoggerTests.cs b/test/Microsoft.IdentityModel.Logging.Tests/ILoggerTests.cs new file mode 100644 index 0000000000..a7505f9fef --- /dev/null +++ b/test/Microsoft.IdentityModel.Logging.Tests/ILoggerTests.cs @@ -0,0 +1,1103 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System; +using System.Collections.Generic; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Microsoft.IdentityModel.JsonWebTokens; +using Microsoft.IdentityModel.Protocols.OpenIdConnect; +using Microsoft.IdentityModel.TestUtils; +using Microsoft.IdentityModel.Tokens; +using Xunit; + +namespace Microsoft.IdentityModel.Logging.Tests +{ + public class LoggerImpl : ILogger + { + public class LogEntry + { + public LogLevel LogLevel { get; set; } + + public EventId EventId { get; set; } + + public object State { get; set; } + + public Exception Exception { get; set; } + } + + private List _logEntries = new List(); + + public LoggerImpl(LogLevel logLevel) + { + LogLevel = logLevel; + } + + public LogLevel LogLevel { get; } = LogLevel.Information; + + public IDisposable BeginScope(TState state) => throw new NotImplementedException(); + + public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception exception, + Func formatter) + { + if (!IsEnabled(logLevel)) + return; + + _logEntries.Add(new LogEntry { LogLevel = logLevel, EventId = eventId, State = state, Exception = exception }); + } + + public IList GetLogEntries() + { + return _logEntries.AsReadOnly(); + } + } + + public class ILoggerTests + { + /// + /// Test that the LogHelper.IsEnabled method returns false when Ilogger is null. + /// + [Fact] + public void ReturnsFalse_WhenLoggerContextIsNull() + { + Assert.False(LogHelper.IsEnabled(LogLevel.Information, null)); + } + + /// + /// Tests that the new LoggerConext throws when passed null to ctor. + /// + [Fact] + public void ThrowsWhenILoggerNull() + { + Assert.Throws(() => new LoggerContext((ILogger)null)); + } + + /// + /// Tests that the LogHelper.LogExceptionMessage method logs exceptions at the correct log levels. + /// + /// level to set ILogger. + /// should we be expecting logs. + [Theory] + [InlineData(LogLevel.Trace, true)] + [InlineData(LogLevel.Debug, true)] + [InlineData(LogLevel.Information, true)] + [InlineData(LogLevel.Warning, true)] + [InlineData(LogLevel.Error, true)] + [InlineData(LogLevel.Critical, false)] + [InlineData(LogLevel.None, false)] + public void LogExceptions_Levels(LogLevel logLevel, bool shouldLogInfo) + { + LoggerImpl logger = new LoggerImpl(logLevel); + string correlationId = Guid.NewGuid().ToString(); + LogHelper.LogExceptionMessage(new Exception("Exception"), new LoggerContext(logger) { CorrelationId = correlationId }); + + Assert.True(logger.GetLogEntries().Count == (shouldLogInfo ? 1 : 0)); + if (shouldLogInfo) + Assert.Contains(correlationId, logger.GetLogEntries()[0].State.ToString()); + } + + /// + /// Tests that the LogHelper.LogInformation method logs information messages at the correct log levels. + /// + /// level to set ILogger. + /// should we be expecting logs. + [Theory] + [InlineData(LogLevel.Trace, true)] + [InlineData(LogLevel.Debug, true)] + [InlineData(LogLevel.Information, true)] + [InlineData(LogLevel.Warning, false)] + [InlineData(LogLevel.Error, false)] + [InlineData(LogLevel.Critical, false)] + [InlineData(LogLevel.None, false)] + public void LogInformation_Levels(LogLevel logLevel, bool shouldLogInfo) + { + string correlationId = Guid.NewGuid().ToString(); + LoggerImpl logger = new LoggerImpl(logLevel); + LogHelper.LogInformation("Information", new LoggerContext(logger) { CorrelationId = correlationId }); + + Assert.True(logger.GetLogEntries().Count == (shouldLogInfo ? 1 : 0)); + if (shouldLogInfo) + Assert.Contains(correlationId, logger.GetLogEntries()[0].State.ToString()); + } + + /// + /// Tests that the LogHelper.LogVerbose method logs verbose messages at the correct log levels. + /// + /// level to set ILogger. + /// should we be expecting logs. + [Theory] + [InlineData(LogLevel.Trace, true)] + [InlineData(LogLevel.Debug, true)] + [InlineData(LogLevel.Information, false)] + [InlineData(LogLevel.Warning, false)] + [InlineData(LogLevel.Error, false)] + [InlineData(LogLevel.Critical, false)] + [InlineData(LogLevel.None, false)] + public void LogVerbose_Levels(LogLevel logLevel, bool shouldLogInfo) + { + string correlationId = Guid.NewGuid().ToString(); + LoggerImpl logger = new LoggerImpl(logLevel); + LogHelper.LogVerbose("Verbose", new LoggerContext(logger) { CorrelationId = correlationId }); + + Assert.True(logger.GetLogEntries().Count == (shouldLogInfo ? 1 : 0)); + if (shouldLogInfo) + Assert.Contains(correlationId, logger.GetLogEntries()[0].State.ToString()); + } + + /// + /// Tests that the LogHelper.LogWarning method logs warnings at the correct log levels. + /// + /// level to set ILogger. + /// should we be expecting logs. + [Theory] + [InlineData(LogLevel.Trace, true)] + [InlineData(LogLevel.Debug, true)] + [InlineData(LogLevel.Information, true)] + [InlineData(LogLevel.Warning, true)] + [InlineData(LogLevel.Error, false)] + [InlineData(LogLevel.Critical, false)] + [InlineData(LogLevel.None, false)] + public void LogWarnings_Levels(LogLevel logLevel, bool shouldLogInfo) + { + string correlationId = Guid.NewGuid().ToString(); + LoggerImpl logger = new LoggerImpl(logLevel); + LogHelper.LogWarning("Warning", new LoggerContext(logger) { CorrelationId = correlationId }); + + Assert.True(logger.GetLogEntries().Count == (shouldLogInfo ? 1 : 0)); + if (shouldLogInfo) + Assert.Contains(correlationId, logger.GetLogEntries()[0].State.ToString()); + } + + /// + /// Tests that the ActivityId and CorrelationId are logged correctly when logging warnings. + /// + /// whether to use an ActivityId. + /// whether to use a CorrelationId. + [Theory] + [InlineData(true, true)] + [InlineData(true, false)] + public void ActivityCorrelationIds(bool useActivityId, bool useCorrelationId) + { + string correlationId = useCorrelationId ? Guid.NewGuid().ToString() : null; + Guid activityId = useActivityId ? Guid.NewGuid() : Guid.Empty; + LoggerImpl logger = new LoggerImpl(LogLevel.Warning); + CallContext callContext = new CallContext(logger) { CorrelationId = correlationId, ActivityId = activityId }; + LogHelper.LogWarning("Warning", callContext); + + if (useCorrelationId) + Assert.Contains(correlationId, logger.GetLogEntries()[0].State.ToString(), StringComparison.InvariantCulture); + + // CorrelationId overrides ActivityId + if (useActivityId && !useCorrelationId) + Assert.Contains(activityId.ToString(), logger.GetLogEntries()[0].State.ToString(), StringComparison.InvariantCulture); + } + + /// + /// Tests related to validating a JSON Web Token (JWT) that are not specific to validation stings like audience, issuer, lifetime, etc. + /// + [Theory, MemberData(nameof(ValidateJsonWebTokenAsyncTestCases), DisableDiscoveryEnumeration = true)] + public async Task ValidateJsonWebTokenAsync(ValidateTokenTheoryData theoryData) + { + CompareContext context = TestUtilities.WriteHeader($"{this}.ValidateTokenAsync", theoryData); + theoryData.ValidationParameters.InstancePropertyBag[TokenValidationParametersExtensions.s_callContextKey] = theoryData.CallContext; + TokenValidationResult result = + await theoryData.Handler.ValidateTokenAsync(theoryData.SecurityToken, theoryData.ValidationParameters); + + TestUtilities.AssertFailIfErrors(context); + + Assert.True(theoryData.Logger.GetLogEntries().Count > 0, "Expected log entries."); + if (theoryData.LogValues.Count > 0) + { + int logCount = 0; + foreach (string logValue in theoryData.LogValues) + { + foreach (var logEntry in theoryData.Logger.GetLogEntries()) + { + if (logEntry.State.ToString().Contains(logValue)) + logCount++; + } + } + + Assert.True(logCount == theoryData.LogValues.Count, + $"Expected log values count: '{theoryData.LogValues.Count}' to match actual count '{logCount}'."); + } + } + + public static TheoryData ValidateJsonWebTokenAsyncTestCases + { + get + { + TheoryData theoryData = new TheoryData(); + JsonWebTokenHandler handler = new JsonWebTokenHandler(); + LoggerImpl logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("TokenIsNotJsonWebToken") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "TokenIsNotJsonWebToken" }, + SecurityToken = new DerivedSecurityToken(), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters() + } + ); + + return theoryData; + } + } + + /// + /// Tests related to validating the audience of a JWT. + /// + [Theory, MemberData(nameof(ValidateJwtAudienceTestCases), DisableDiscoveryEnumeration = true)] + public async Task ValidateJwtAudienceAsync(ValidateTokenTheoryData theoryData) + { + CompareContext context = TestUtilities.WriteHeader($"{this}.ValidateTokenAsync", theoryData); + theoryData.ValidationParameters.InstancePropertyBag[TokenValidationParametersExtensions.s_callContextKey] = theoryData.CallContext; + TokenValidationResult result = + await theoryData.Handler.ValidateTokenAsync(theoryData.SecurityToken, theoryData.ValidationParameters); + + TestUtilities.AssertFailIfErrors(context); + + if (theoryData.LogValues.Count > 0) + { + Assert.True(theoryData.Logger.GetLogEntries().Count > 0, "Expected log entries."); + + int logCount = 0; + foreach (string logValue in theoryData.LogValues) + { + foreach (var logEntry in theoryData.Logger.GetLogEntries()) + { + if (logEntry.State.ToString().Contains(logValue)) + logCount++; + } + } + + Assert.True(logCount == theoryData.LogValues.Count, + $"Expected log values count: '{theoryData.LogValues.Count}' to match actual count '{logCount}'."); + } + } + + public static TheoryData ValidateJwtAudienceTestCases + { + get + { + TheoryData theoryData = new TheoryData(); + JsonWebTokenHandler handler = new JsonWebTokenHandler(); + LoggerImpl logger = new LoggerImpl(LogLevel.Warning); + + SecurityTokenDescriptor securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims) + }; + + string jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + + // Valid audience (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("ValidAudience") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "ValidAudience" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // No audience in token (failure) + logger = new LoggerImpl(LogLevel.Warning); + var noAudienceDescriptor = new SecurityTokenDescriptor + { + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims) + }; + string jwtNoAudience = handler.CreateToken(noAudienceDescriptor); + theoryData.Add( + new ValidateTokenTheoryData("NoAudienceInToken", new List { "IDX10206:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoAudienceInToken" }, + SecurityToken = new JsonWebToken(jwtNoAudience), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // RequireAudience = false and no audience (skipped) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NoAudience_RequireAudienceFalse", new List { "IDX10277:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoAudience_RequireAudienceFalse" }, + SecurityToken = new JsonWebToken(jwtNoAudience), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + RequireAudience = false + } + } + ); + + // RequireAudience = true and no audience + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + + + new ValidateTokenTheoryData("NoAudience_RequireAudienceTrue", new List { "IDX10206:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoAudience_RequireAudienceTrue" }, + SecurityToken = new JsonWebToken(jwtNoAudience), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // ValidAudience and ValidAudiences both null (failure) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NoValidAudienceOrAudiences", new List { "IDX10208:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoValidAudienceOrAudiences" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = null, + ValidAudiences = null, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom AudienceValidator (skipped, always returns true) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomAudienceValidator_True") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomAudienceValidator_True" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + AudienceValidator = (audiences, token, parameters) => true, + ValidAudience = "notused", + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom AudienceValidator (skipped, always returns false) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomAudienceValidator_False", new List { { "IDX10231:" } }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomAudienceValidator_False" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + AudienceValidator = (audiences, token, parameters) => false, + ValidAudience = "notused", + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + theoryData.Add( + new ValidateTokenTheoryData("DoNotValidateAudience", new List { "IDX10233:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "DoNotValidateAudience" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Guid.NewGuid().ToString(), + ValidateAudience = false, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + + } + ); + + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData( + "DoNotValidateAudienceAndIssuer", + new List + { + $"IDX10235", + $"IDX10233" + }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "DoNotValidateAudienceAndIssuer" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Guid.NewGuid().ToString(), + ValidIssuer = Guid.NewGuid().ToString(), + ValidateAudience = false, + ValidateIssuer = false, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + + } + ); + + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("InvalidAudience") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "InvalidAudience" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Guid.NewGuid().ToString(), + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + return theoryData; + } + } + + /// + /// Tests related to validating the issuer of a JWT. + /// + [Theory, MemberData(nameof(ValidateJwtIssuerTestCases), DisableDiscoveryEnumeration = true)] + public async Task ValidateJwtIssuerAsync(ValidateTokenTheoryData theoryData) + { + CompareContext context = TestUtilities.WriteHeader($"{this}.ValidateJwtIssuerAsync", theoryData); + theoryData.ValidationParameters.InstancePropertyBag[TokenValidationParametersExtensions.s_callContextKey] = theoryData.CallContext; + TokenValidationResult result = + await theoryData.Handler.ValidateTokenAsync(theoryData.SecurityToken, theoryData.ValidationParameters); + + if (theoryData.LogValues.Count > 0) + { + Assert.True(theoryData.Logger.GetLogEntries().Count > 0, "Expected log entries."); + + int logCount = 0; + foreach (string logValue in theoryData.LogValues) + { + foreach (var logEntry in theoryData.Logger.GetLogEntries()) + { + if (logEntry.State.ToString().Contains(logValue)) + logCount++; + } + } + + Assert.True(logCount == theoryData.LogValues.Count, + $"Expected log values count: '{theoryData.LogValues.Count}' to match actual count '{logCount}'."); + } + } + + public static TheoryData ValidateJwtIssuerTestCases + { + get + { + TheoryData theoryData = new TheoryData(); + JsonWebTokenHandler handler = new JsonWebTokenHandler(); + LoggerImpl logger = new LoggerImpl(LogLevel.Warning); + + SecurityTokenDescriptor securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims) + }; + + string jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + + theoryData.Add( + new ValidateTokenTheoryData("DoNotValidateIssuer", new List { "IDX10235:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "DoNotValidateIssuer" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidateIssuer = false, + ValidIssuer = Guid.NewGuid().ToString(), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + + } + ); + + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("InvalidIssuer") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "InvalidIssuer" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Guid.NewGuid().ToString(), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Valid issuer (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("ValidIssuer") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "ValidIssuer" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Null/whitespace issuer (failure) + logger = new LoggerImpl(LogLevel.Warning); + var noIssuerDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims) + }; + string jwtNoIssuer = handler.CreateToken(noIssuerDescriptor); + theoryData.Add( + new ValidateTokenTheoryData("NullIssuer", new List { "IDX10211:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NullIssuer" }, + SecurityToken = new JsonWebToken(jwtNoIssuer), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // ValidIssuer, ValidIssuers, configuration.Issuer all null/empty (failure) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NoValidIssuerOrIssuers", new List { "IDX10204:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoValidIssuerOrIssuers" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = null, + ValidIssuers = null, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Issuer matches configuration.Issuer (success) + logger = new LoggerImpl(LogLevel.Warning); + var config = new OpenIdConnectConfiguration { Issuer = Default.Issuer }; + theoryData.Add( + new ValidateTokenTheoryData("IssuerMatchesConfiguration") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "IssuerMatchesConfiguration" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + Configuration = config, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = "not-the-issuer", + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Issuer matches one of ValidIssuers (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("IssuerMatchesValidIssuers") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "IssuerMatchesValidIssuers" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = "not-the-issuer", + ValidIssuers = new[] { "foo", Default.Issuer, "bar" }, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidator (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidator_True") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidator_True" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidator = (issuer, token, parameters) => issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidator (failure) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidator_False", new List { "IDX10205:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidator_False" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidator = (issuer, token, parameters) => + throw new SecurityTokenInvalidIssuerException( + LogHelper.FormatInvariant( + Tokens.LogMessages.IDX10205, + Default.Issuer, + "Issuers", + "Issuer", + "CurrentConfiguration.Issuer")), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidatorAsync (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidatorAsync_True") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidatorAsync_True" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidatorAsync = (issuer, token, parameters) => new ValueTask(issuer), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidatorAsync (failure) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidatorAsync_False", new List { "IDX10205:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidatorAsync_False" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidatorAsync = (issuer, token, parameters) => + throw new SecurityTokenInvalidIssuerException( + LogHelper.FormatInvariant( + Tokens.LogMessages.IDX10205, + Default.Issuer, + "Issuers", + "Issuer", + "CurrentConfiguration.Issuer")), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidatorUsingConfiguration (success) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidatorUsingConfiguration_True") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidatorUsingConfiguration_True" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + Configuration = config, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidatorUsingConfiguration = (issuer, token, parameters, conf) => issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // Custom IssuerValidatorUsingConfiguration (failure) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomIssuerValidatorUsingConfiguration_False", new List { "IDX10205:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomIssuerValidatorUsingConfiguration_False" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + Configuration = config, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + IssuerValidatorUsingConfiguration = (issuer, token, parameters, conf) => + throw new SecurityTokenInvalidIssuerException( + LogHelper.FormatInvariant( + Tokens.LogMessages.IDX10205, + Default.Issuer, + "Issuers", + "Issuer", + "CurrentConfiguration.Issuer")), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + return theoryData; + } + } + + /// + /// Tests related to validating the lifetime of a JWT. + /// + [Theory, MemberData(nameof(ValidateJwtLifetimeTestCases), DisableDiscoveryEnumeration = true)] + public async Task ValidateJwtLifetimeAsync(ValidateTokenTheoryData theoryData) + { + CompareContext context = TestUtilities.WriteHeader($"{this}.ValidateJwtLifetimeAsync", theoryData); + theoryData.ValidationParameters.InstancePropertyBag[TokenValidationParametersExtensions.s_callContextKey] = theoryData.CallContext; + TokenValidationResult result = + await theoryData.Handler.ValidateTokenAsync(theoryData.SecurityToken, theoryData.ValidationParameters); + + int logCount = 0; + + if (theoryData.LogValues.Count > 0) + { + Assert.True(theoryData.Logger.GetLogEntries().Count > 0, "Expected log entries."); + + foreach (string logValue in theoryData.LogValues) + { + foreach (var logEntry in theoryData.Logger.GetLogEntries()) + { + if (logEntry.State.ToString().Contains(logValue)) + logCount++; + } + } + } + + Assert.True(logCount == theoryData.LogValues.Count, + $"Expected log values count: '{theoryData.LogValues.Count}' to match actual count '{logCount}'."); + } + + public static TheoryData ValidateJwtLifetimeTestCases + { + get + { + TheoryData theoryData = new TheoryData(); + JsonWebTokenHandler handler = new JsonWebTokenHandler() { SetDefaultTimesOnTokenCreation = false }; + LoggerImpl logger = new LoggerImpl(LogLevel.Warning); + SecurityTokenDescriptor securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims), + Expires = DateTime.UtcNow.AddDays(-5), + NotBefore = DateTime.UtcNow.AddDays(-10) + }; + + string jwt = handler.CreateToken(securityTokenDescriptor); + theoryData.Add( + new ValidateTokenTheoryData("ExpiredToken", new List { { "IDX10223:" } }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "ExpiredToken" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Guid.NewGuid().ToString(), + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims), + Expires = DateTime.UtcNow.AddDays(1) + }; + + jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + + theoryData.Add( + new ValidateTokenTheoryData("ValidLifetime") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "ValidLifetime" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + }); + + // Not yet valid token + securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims), + NotBefore = DateTime.UtcNow.AddMinutes(10), + Expires = DateTime.UtcNow.AddMinutes(60) + }; + + jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NotYetValidToken", new List { "IDX10222:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NotYetValidToken" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // NotBefore > Expires + securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims), + NotBefore = DateTime.UtcNow.AddMinutes(10), + Expires = DateTime.UtcNow.AddMinutes(5) + }; + + jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NotBeforeAfterExpires", new List { "IDX10224:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NotBeforeAfterExpires" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + } + } + ); + + // No expiration, RequireExpirationTime = true (should fail) + securityTokenDescriptor = new SecurityTokenDescriptor + { + Audience = Default.Audience, + Issuer = Default.Issuer, + SigningCredentials = Default.AsymmetricSigningCredentials, + Subject = new CaseSensitiveClaimsIdentity(ClaimSets.DefaultClaims), + }; + + jwt = handler.CreateToken(securityTokenDescriptor); + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NoExpiration_RequireExpirationTimeTrue", new List { "IDX10225:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoExpiration_RequireExpirationTimeTrue" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + RequireExpirationTime = true + } + } + ); + + // No expiration, RequireExpirationTime = false (should succeed) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("NoExpiration_RequireExpirationTimeFalse", new List { "IDX10238:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "NoExpiration_RequireExpirationTimeFalse" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + ValidateLifetime = false + } + } + ); + + // ValidateLifetime = false (should skip validation) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("ValidateLifetimeFalse", new List { "IDX10238:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "ValidateLifetimeFalse" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + ValidateLifetime = false + } + } + ); + + // Custom LifetimeValidator returns true (should succeed) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomLifetimeValidator_True") + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomLifetimeValidator_True" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + LifetimeValidator = (notBefore, expires, token, parameters) => true + } + } + ); + + // Custom LifetimeValidator returns false (should fail) + logger = new LoggerImpl(LogLevel.Warning); + theoryData.Add( + new ValidateTokenTheoryData("CustomLifetimeValidator_False", new List { "IDX10230:" }) + { + Logger = logger, + CallContext = new CallContext(logger) { DebugId = "CustomLifetimeValidator_False" }, + SecurityToken = new JsonWebToken(jwt), + SigningCredentials = Default.AsymmetricSigningCredentials, + ValidationParameters = new TokenValidationParameters + { + ValidAudience = Default.Audience, + ValidIssuer = Default.Issuer, + IssuerSigningKey = Default.AsymmetricSigningKey, + LifetimeValidator = (notBefore, expires, token, parameters) => false + } + } + ); + + return theoryData; + } + } + + public class ValidateTokenTheoryData : TheoryDataBase + { + public ValidateTokenTheoryData(string testId) : base(testId) { } + public ValidateTokenTheoryData(string testId, IList logValues) : base(testId) + { + LogValues = logValues; + } + public BaseConfiguration Configuration { get; set; } + public JsonWebTokenHandler Handler { get; set; } = new JsonWebTokenHandler(); + public LoggerImpl Logger { get; set; } = new LoggerImpl(LogLevel.Warning); + public IList LogValues { get; } = new List(); + public SecurityToken SecurityToken { get; set; } + public SigningCredentials SigningCredentials { get; set; } + public TokenValidationParameters ValidationParameters { get; set; } + } + } +} diff --git a/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs b/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs index 3dae66def8..5e058b6b40 100644 --- a/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs +++ b/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs @@ -14,6 +14,7 @@ namespace Microsoft.IdentityModel.Logging.Tests { + [Collection("PIITests")] public class PIITests { // Used for formatting a message for testing with one parameter. @@ -21,6 +22,11 @@ public class PIITests // Used for formatting a message for testing with two parameters. private const string TestMessageTwoParams = "This is the first parameter '{0}'. This is the second parameter '{1}'."; + public PIITests() + { + IdentityModelEventSource.ShowPII = true; + } + [Fact] public void LogOpenIdConnectProtocolExceptions() { @@ -193,6 +199,10 @@ public void LogExceptionAsArgument() LogHelper.LogExceptionMessage(EventLevel.Error, new ArgumentException(LogHelper.FormatInvariant("Main exception 1: {0}", new SecurityTokenCompressionFailedException("custom inner exception")))); LogHelper.LogExceptionMessage(EventLevel.Error, new ArgumentException(LogHelper.FormatInvariant("Main exception 2: {0}", new InvalidOperationException("system exception")))); + Console.WriteLine($"TraceBuffer: '{listener.TraceBuffer}'"); + Console.WriteLine($"Expected1: Main exception 1: Microsoft.IdentityModel.Tokens.SecurityTokenCompressionFailedException: custom inner exception"); + Console.WriteLine($"Expected2: Main exception 2: [PII of type 'System.InvalidOperationException' is hidden. For more details, see https://aka.ms/IdentityModel/PII.]"); + Assert.Contains("Main exception 1: Microsoft.IdentityModel.Tokens.SecurityTokenCompressionFailedException: custom inner exception", listener.TraceBuffer); Assert.Contains("Main exception 2: [PII of type 'System.InvalidOperationException' is hidden. For more details, see https://aka.ms/IdentityModel/PII.]", listener.TraceBuffer); } diff --git a/test/Microsoft.IdentityModel.Logging.Tests/TestLogger.cs b/test/Microsoft.IdentityModel.Logging.Tests/TestLogger.cs index d001ef48bc..e5dd28ce0e 100644 --- a/test/Microsoft.IdentityModel.Logging.Tests/TestLogger.cs +++ b/test/Microsoft.IdentityModel.Logging.Tests/TestLogger.cs @@ -1,4 +1,7 @@ -using System; +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System; using System.Collections.Generic; using System.Linq; using Microsoft.IdentityModel.Abstractions; From b3e70916ba8b06809470b483f84d4b684f01aa64 Mon Sep 17 00:00:00 2001 From: id4s Date: Tue, 5 Aug 2025 10:18:43 -0700 Subject: [PATCH 2/2] turn off OII --- test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs b/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs index 5e058b6b40..811234a39f 100644 --- a/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs +++ b/test/Microsoft.IdentityModel.Logging.Tests/PIITests.cs @@ -24,7 +24,7 @@ public class PIITests public PIITests() { - IdentityModelEventSource.ShowPII = true; + IdentityModelEventSource.ShowPII = false; } [Fact]