Add logging to the new validation model (#3054)

* Added Microsoft.Extensions.Logging.Abstractions to Microsoft.IdentityModel.Tokens to access ILogger * Added LoggingEventIds to store event ids used by the logging methods in M.IM.Tokens * Added logging to ValidationError and ValidatedToken to log the results obtained from ValidateTokenAsync after the fact. * Moved dependency version to dependencies.props * Update src/Microsoft.IdentityModel.Tokens/Validation/Results/ValidatedToken.cs Co-authored-by: Westin Musser <127992899+westin-m@users.noreply.github.com> * Sorted dependency versions based on PR feedback --------- Co-authored-by: Westin Musser <127992899+westin-m@users.noreply.github.com>
AzureAD · Dec 9, 2024 · 853b1fb · 853b1fb
1 parent 039e8f8
commit 853b1fb
Show file tree

Hide file tree

Showing 6 changed files with 125 additions and 4 deletions.
diff --git a/build/dependencies.props b/build/dependencies.props
@@ -5,6 +5,7 @@
     <BannedApiAnalyzersVersion>3.3.4</BannedApiAnalyzersVersion>
     <MicrosoftBclTimeProviderVersion>8.0.1</MicrosoftBclTimeProviderVersion>
     <MicrosoftCSharpVersion>4.5.0</MicrosoftCSharpVersion>
+    <MicrosoftExtensionsLoggingAbstractionsVersion>8.0.2</MicrosoftExtensionsLoggingAbstractionsVersion>
     <MicrosoftSourceLinkGitHubVersion>1.0.0</MicrosoftSourceLinkGitHubVersion>
     <NetStandardVersion>2.0.3</NetStandardVersion>
     <NewtonsoftVersion>13.0.3</NewtonsoftVersion>

diff --git a/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt b/src/Microsoft.IdentityModel.Tokens/InternalAPI.Unshipped.txt
@@ -27,6 +27,7 @@ Microsoft.IdentityModel.Tokens.IssuerValidationSource.IssuerMatchedValidationPar
 Microsoft.IdentityModel.Tokens.LifetimeValidationError.Expires.get -> System.DateTime?
 Microsoft.IdentityModel.Tokens.LifetimeValidationError.LifetimeValidationError(Microsoft.IdentityModel.Tokens.MessageDetail messageDetail, Microsoft.IdentityModel.Tokens.ValidationFailureType validationFailureType, System.Type exceptionType, System.Diagnostics.StackFrame stackFrame, System.DateTime? notBefore, System.DateTime? expires, System.Exception innerException = null) -> void
 Microsoft.IdentityModel.Tokens.LifetimeValidationError.NotBefore.get -> System.DateTime?
+Microsoft.IdentityModel.Tokens.LoggingEventId
 Microsoft.IdentityModel.Tokens.SecurityTokenInvalidOperationException
 Microsoft.IdentityModel.Tokens.SecurityTokenInvalidOperationException.SecurityTokenInvalidOperationException() -> void
 Microsoft.IdentityModel.Tokens.SecurityTokenInvalidOperationException.SecurityTokenInvalidOperationException(string message) -> void
@@ -43,13 +44,16 @@ Microsoft.IdentityModel.Tokens.TokenTypeValidationError.InvalidTokenType.get ->
 Microsoft.IdentityModel.Tokens.TokenTypeValidationError.TokenTypeValidationError(Microsoft.IdentityModel.Tokens.MessageDetail messageDetail, Microsoft.IdentityModel.Tokens.ValidationFailureType validationFailureType, System.Type exceptionType, System.Diagnostics.StackFrame stackFrame, string invalidTokenType, System.Exception innerException = null) -> void
 Microsoft.IdentityModel.Tokens.TokenValidationParameters.TimeProvider.get -> System.TimeProvider
 Microsoft.IdentityModel.Tokens.TokenValidationParameters.TimeProvider.set -> void
+Microsoft.IdentityModel.Tokens.ValidatedToken.Log(Microsoft.Extensions.Logging.ILogger logger) -> void
 Microsoft.IdentityModel.Tokens.ValidationError.AddCurrentStackFrame(string filePath = "", int lineNumber = 0, int skipFrames = 1) -> Microsoft.IdentityModel.Tokens.ValidationError
 Microsoft.IdentityModel.Tokens.ValidationError.GetException(System.Type exceptionType, System.Exception innerException) -> System.Exception
+Microsoft.IdentityModel.Tokens.ValidationError.Log(Microsoft.Extensions.Logging.ILogger logger) -> void
 Microsoft.IdentityModel.Tokens.ValidationError.ValidationError(Microsoft.IdentityModel.Tokens.MessageDetail messageDetail, Microsoft.IdentityModel.Tokens.ValidationFailureType validationFailureType, System.Type exceptionType, System.Diagnostics.StackFrame stackFrame, System.Exception innerException = null) -> void
 Microsoft.IdentityModel.Tokens.ValidationParameters.TokenTypeValidator.get -> Microsoft.IdentityModel.Tokens.TokenTypeValidationDelegate
 Microsoft.IdentityModel.Tokens.ValidationParameters.TokenTypeValidator.set -> void
 Microsoft.IdentityModel.Tokens.ValidationResult<TResult>.Error.get -> Microsoft.IdentityModel.Tokens.ValidationError
 Microsoft.IdentityModel.Tokens.ValidationResult<TResult>.IsValid.get -> bool
+Microsoft.IdentityModel.Tokens.ValidationResult<TResult>.Log(Microsoft.Extensions.Logging.ILogger logger) -> void
 Microsoft.IdentityModel.Tokens.ValidationResult<TResult>.Result.get -> TResult
 override Microsoft.IdentityModel.Tokens.AlgorithmValidationError.GetException() -> System.Exception
 override Microsoft.IdentityModel.Tokens.IssuerSigningKeyValidationError.GetException() -> System.Exception
@@ -62,6 +66,8 @@ static Microsoft.IdentityModel.Tokens.TokenReplayValidationError.NullParameter(s
 static Microsoft.IdentityModel.Tokens.TokenTypeValidationError.NullParameter(string parameterName, System.Diagnostics.StackFrame stackFrame) -> Microsoft.IdentityModel.Tokens.TokenTypeValidationError
 static Microsoft.IdentityModel.Tokens.Utility.SerializeAsSingleCommaDelimitedString(System.Collections.Generic.IList<string> strings) -> string
 static Microsoft.IdentityModel.Tokens.ValidationError.GetCurrentStackFrame(string filePath = "", int lineNumber = 0, int skipFrames = 1) -> System.Diagnostics.StackFrame
+static readonly Microsoft.IdentityModel.Tokens.LoggingEventId.TokenValidationFailed -> Microsoft.Extensions.Logging.EventId
+static readonly Microsoft.IdentityModel.Tokens.LoggingEventId.TokenValidationSucceeded -> Microsoft.Extensions.Logging.EventId
 static readonly Microsoft.IdentityModel.Tokens.ValidationFailureType.AlgorithmValidatorThrew -> Microsoft.IdentityModel.Tokens.ValidationFailureType
 static readonly Microsoft.IdentityModel.Tokens.ValidationFailureType.AudienceValidatorThrew -> Microsoft.IdentityModel.Tokens.ValidationFailureType
 static readonly Microsoft.IdentityModel.Tokens.ValidationFailureType.IssuerSigningKeyValidatorThrew -> Microsoft.IdentityModel.Tokens.ValidationFailureType

diff --git a/src/Microsoft.IdentityModel.Tokens/LoggingEventId.cs b/src/Microsoft.IdentityModel.Tokens/LoggingEventId.cs
@@ -0,0 +1,14 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.IdentityModel.Tokens
+{
+    internal static class LoggingEventId
+    {
+        // TokenValidation EventIds 100+
+        internal static readonly EventId TokenValidationFailed = new(100, "TokenValidationFailed");
+        internal static readonly EventId TokenValidationSucceeded = new(101, "TokenValidationSucceeded");
+    }
+}
diff --git a/src/Microsoft.IdentityModel.Tokens/Microsoft.IdentityModel.Tokens.csproj b/src/Microsoft.IdentityModel.Tokens/Microsoft.IdentityModel.Tokens.csproj
@@ -72,5 +72,9 @@
     <AdditionalFiles Include="PublicAPI/$(TargetFramework)/InternalAPI.Shipped.txt" />
     <AdditionalFiles Include="PublicAPI/$(TargetFramework)/InternalAPI.Unshipped.txt" />
   </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="$(MicrosoftExtensionsLoggingAbstractionsVersion)" />
+  </ItemGroup>
 
 </Project>
diff --git a/src/Microsoft.IdentityModel.Tokens/Validation/Results/Details/ValidationError.cs b/src/Microsoft.IdentityModel.Tokens/Validation/Results/Details/ValidationError.cs
@@ -6,6 +6,7 @@
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Runtime.CompilerServices;
+using Microsoft.Extensions.Logging;
 using Microsoft.IdentityModel.Logging;
 
 #nullable enable
@@ -183,6 +184,11 @@ internal Exception GetException(Type exceptionType, Exception? innerException)
             return exception;
         }
 
+        internal void Log(ILogger logger)
+        {
+            Logger.TokenValidationFailed(logger, FailureType.Name, MessageDetail.Message);
+        }
+
         internal static ValidationError NullParameter(string parameterName, StackFrame stackFrame) => new(
             MessageDetail.NullParameter(parameterName),
             ValidationFailureType.NullArgument,
@@ -261,6 +267,27 @@ internal static StackFrame GetCurrentStackFrame(
 
         // ConcurrentDictionary is thread-safe and only locks when adding a new item.
         private static ConcurrentDictionary<string, StackFrame> CachedStackFrames { get; } = new();
+
+        private static class Logger
+        {
+            private static readonly Action<ILogger, string, string, Exception?> s_tokenValidationFailed =
+                LoggerMessage.Define<string, string>(
+                    LogLevel.Information,
+                    LoggingEventId.TokenValidationFailed,
+                    "[MsIdentityModel] The token validation was unsuccessful due to: {ValidationFailureType} " +
+                    "Error message provided: {ValidationErrorMessage}");
+
+            /// <summary>
+            /// Logger for handling failures in token validation.
+            /// </summary>
+            /// <param name="logger">ILogger.</param>
+            /// <param name="validationFailureType">The cause of the failure.</param>
+            /// <param name="messageDetail">The message provided as part of the failure.</param>
+            public static void TokenValidationFailed(
+                ILogger logger,
+                string validationFailureType,
+                string messageDetail) => s_tokenValidationFailed(logger, validationFailureType, messageDetail, null);
+        }
     }
 }
 #nullable restore
diff --git a/src/Microsoft.IdentityModel.Tokens/Validation/Results/ValidatedToken.cs b/src/Microsoft.IdentityModel.Tokens/Validation/Results/ValidatedToken.cs
@@ -6,6 +6,7 @@
 using System.Diagnostics;
 using System.Security.Claims;
 using System.Threading;
+using Microsoft.Extensions.Logging;
 
 #nullable enable
 namespace Microsoft.IdentityModel.Tokens
@@ -34,11 +35,17 @@ internal ValidatedToken(
         /// <summary>
         /// Logs the validation result.
         /// </summary>
-#pragma warning disable CA1822 // Mark members as static
-        public void Log()
-#pragma warning restore CA1822 // Mark members as static
+        public void Log(ILogger logger)
         {
-            // TODO - Do we need this, how will it work?
+            Logger.TokenValidationSucceeded(
+                logger,
+                ValidatedAudience ?? "none",
+                ValidatedLifetime,
+                ValidatedIssuer,
+                ValidatedTokenType,
+                ValidatedSigningKey?.KeyId ?? "none",
+                ActorValidationResult is not null
+            );
         }
 
         public SecurityToken SecurityToken { get; private set; }
@@ -168,6 +175,68 @@ private object ClaimsIdentitySyncObj
             }
         }
         #endregion
+
+        #region Logging
+        private static class Logger
+        {
+            private static readonly Action<ILogger, string, string, Exception?> s_tokenValidationFailed =
+                LoggerMessage.Define<string, string>(
+                    LogLevel.Information,
+                    LoggingEventId.TokenValidationFailed,
+                    "[MsIdentityModel] The token validation was unsuccessful due to: {ValidationFailureType} " +
+                    "Error message provided: {ValidationErrorMessage}");
+
+            /// <summary>
+            /// Logger for handling failures in token validation.
+            /// </summary>
+            /// <param name="logger">ILogger.</param>
+            /// <param name="validationFailureType">The cause of the failure.</param>
+            /// <param name="messageDetail">The message provided as part of the failure.</param>
+            public static void TokenValidationFailed(
+                ILogger logger,
+                ValidationFailureType validationFailureType,
+                MessageDetail messageDetail) => s_tokenValidationFailed(logger, validationFailureType.Name, messageDetail.Message, null);
+
+            private static readonly Action<ILogger, string, ValidatedLifetime?, ValidatedIssuer?, ValidatedTokenType?, string, bool, Exception?> s_tokenValidationSucceeded =
+                LoggerMessage.Define<string, ValidatedLifetime?, ValidatedIssuer?, ValidatedTokenType?, string, bool>(
+                    LogLevel.Debug,
+                    LoggingEventId.TokenValidationSucceeded,
+                    "[MsIdentityModel] The token validation was successful. " +
+                    "Validated audience: {ValidatedAudience} " +
+                    "Validated lifetime: {ValidatedLifetime} " +
+                    "Validated issuer: {ValidatedIssuer} " +
+                    "Validated token type: {ValidatedTokenType} " +
+                    "Validated signing key id: {ValidatedSigningKeyId} " +
+                    "Actor was validated: {ActorWasValidated}");
+
+            /// <summary>
+            /// Logger for handling successful token validation.
+            /// </summary>
+            /// <param name="logger">The instance to be used to log.</param>
+            /// <param name="validatedAudience">The audience that was validated.</param>
+            /// <param name="validatedLifetime">The lifetime that was validated.</param>
+            /// <param name="validatedIssuer">The issuer that was validated.</param>
+            /// <param name="validatedTokenType">The token type that was validated.</param>
+            /// <param name="validatedSigningKeyId">The signing key id that was validated.</param>
+            /// <param name="actorWasValidated">Whether the actor was validated.</param>
+            public static void TokenValidationSucceeded(
+                ILogger logger,
+                string validatedAudience,
+                ValidatedLifetime? validatedLifetime,
+                ValidatedIssuer? validatedIssuer,
+                ValidatedTokenType? validatedTokenType,
+                string validatedSigningKeyId,
+                bool actorWasValidated) => s_tokenValidationSucceeded(
+                    logger,
+                    validatedAudience,
+                    validatedLifetime,
+                    validatedIssuer,
+                    validatedTokenType,
+                    validatedSigningKeyId,
+                    actorWasValidated,
+                    null);
+        }
+        #endregion
     }
 }
 #nullable disable