Provide support to Log using ILogger

Author: HP712

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<TokenValidationResult> ValidateTokenAsync(string toke
         public override async Task<TokenValidationResult> 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<ArgumentException>(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<TokenValidationResult> ValidateTokenAsync(
             TokenValidationParameters validationParameters)
         {
             BaseConfiguration currentConfiguration = null;
+
             if (validationParameters.ConfigurationManager != null)
             {
                 try
@@ -493,7 +516,11 @@ internal async ValueTask<TokenValidationResult> 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()));
                 }
             }
 

src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.cs

@@ -15,7 +15,7 @@
 namespace Microsoft.IdentityModel.JsonWebTokens
 {
     /// <summary>
-    /// A <see cref="SecurityTokenHandler"/> designed for creating and validating JSON Web Tokens.
+    /// A <see cref="TokenHandler"/> designed for creating and validating JSON Web Tokens.
     /// See: <see href="https://datatracker.ietf.org/doc/html/rfc7519"/> and <see href="https://www.rfc-editor.org/info/rfc7515"/>.
     /// </summary>
     public partial class JsonWebTokenHandler : TokenHandler

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

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; }
         }
 
+        /// <summary>
+        /// Gets a boolean indicating whether logging is enabled at the specified LogLevel.
+        /// </summary>
+        /// <param name="logLevel">The log level</param>
+        /// <param name="loggerContext">A <see cref="LoggerContext"/> that contains logging control including <see cref="ILogger"/>.</param>
+        /// <returns><see langword="true"/> if logging is enabled at the specified level; otherwise, <see langword="false"/>.</returns>
+        internal static bool IsEnabled(LogLevel logLevel, LoggerContext loggerContext)
+        {
+            return loggerContext?.Logger?.IsEnabled(logLevel) ?? false;
+        }
+
         /// <summary>
         /// Gets whether logging is enabled at the specified <see cref="EventLogLevel"/>."/>
         /// </summary>
@@ -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;
+        }
+
+        /// <summary>
+        /// Logs an exception using the listeners that have been enabled.
+        /// </summary>
+        /// <param name="exception">The exception to log.</param>
+        /// <param name="loggerContext">The <see cref="LoggerContext"/> contains information useful for logging and debugging.</param>
+        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));
+        }
+
+        /// <summary>
+        /// Logs at the information level to the listeners that have been enabled.
+        /// </summary>
+        /// <param name="message">The log message.</param>
+        /// <param name="loggerContext">A <see cref="LoggerContext"/> that contains logging control including <see cref="ILogger"/>.</param>
+        /// <param name="args">An object array that contains zero or more objects to format.</param>
+        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);
         }
 
         /// <summary>
@@ -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));
+        }
+
+        /// <summary>
+        /// Logs at the verbose level to the listeners that have been enabled.
+        /// </summary>
+        /// <param name="message">The log message.</param>
+        /// <param name="loggerContext">A <see cref="LoggerContext"/> that contains logging control including <see cref="ILogger"/>.</param>
+        /// <param name="args">An object array that contains zero or more objects to format.</param>
+        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);
         }
 
         /// <summary>
@@ -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));
+        }
+
+        /// <summary>
+        /// Logs at the warning level to the listeners that have been enabled.
+        /// </summary>
+        /// <param name="message">The log message.</param>
+        /// <param name="loggerContext">A <see cref="LoggerContext"/> that contains logging control including <see cref="ILogger"/>.</param>
+        public static void LogWarning(string message, LoggerContext loggerContext)
+        {
+            LogWarning(message, loggerContext, null);
+        }
+
+        /// <summary>
+        /// Logs at the warning level to the listeners that have been enabled.
+        /// </summary>
+        /// <param name="message">The log message.</param>
+        /// <param name="loggerContext">A <see cref="LoggerContext"/> that contains logging control including <see cref="ILogger"/>.</param>
+        /// <param name="args">An object array that contains zero or more objects to format.</param>
+        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);
         }
 
         /// <summary>
@@ -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<object, strin
         /// <param name="innerException"><see cref="Exception"/></param>
         /// <param name="message">The log message.</param>
         /// <param name="args">An object array that contains zero or more objects to format.</param>
-        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);
+        }
+
+        /// <summary>
+        /// Creates a <see cref="LogEntry"/> by using the provided event level, exception argument, string argument and arguments list.
+        /// </summary>
+        /// <param name="eventLogLevel"><see cref="EventLogLevel"/></param>
+        /// <param name="innerException"><see cref="Exception"/></param>
+        /// <param name="message">The log message.</param>
+        /// <param name="correlationId">The CorrelationId is set by caller to coordinate logs between services.</param>
+        /// <param name="args">An object array that contains zero or more objects to format.</param>
+        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;
+                }
+            }
+        }
     }
 }