Add debugg logging for DataProtectorTokenProvider.ValidationAsync (#10739)

src/Identity/Core/ref/Microsoft.AspNetCore.Identity.netcoreapp3.0.cs

@@ -21,7 +21,8 @@ namespace Microsoft.AspNetCore.Identity
     }
     public partial class DataProtectorTokenProvider<TUser> : Microsoft.AspNetCore.Identity.IUserTwoFactorTokenProvider<TUser> where TUser : class
     {
-        public DataProtectorTokenProvider(Microsoft.AspNetCore.DataProtection.IDataProtectionProvider dataProtectionProvider, Microsoft.Extensions.Options.IOptions<Microsoft.AspNetCore.Identity.DataProtectionTokenProviderOptions> options) { }
+        public DataProtectorTokenProvider(Microsoft.AspNetCore.DataProtection.IDataProtectionProvider dataProtectionProvider, Microsoft.Extensions.Options.IOptions<Microsoft.AspNetCore.Identity.DataProtectionTokenProviderOptions> options, Microsoft.Extensions.Logging.ILogger<Microsoft.AspNetCore.Identity.DataProtectorTokenProvider<TUser>> logger) { }
+        public Microsoft.Extensions.Logging.ILogger<Microsoft.AspNetCore.Identity.DataProtectorTokenProvider<TUser>> Logger { [System.Runtime.CompilerServices.CompilerGeneratedAttribute]get { throw null; } }
         public string Name { get { throw null; } }
         protected Microsoft.AspNetCore.Identity.DataProtectionTokenProviderOptions Options { [System.Runtime.CompilerServices.CompilerGeneratedAttribute]get { throw null; } }
         protected Microsoft.AspNetCore.DataProtection.IDataProtector Protector { [System.Runtime.CompilerServices.CompilerGeneratedAttribute]get { throw null; } }

src/Identity/Core/src/DataProtectorTokenProvider.cs

@@ -5,7 +5,9 @@ using System;
 using System.IO;
 using System.Text;
 using System.Threading.Tasks;
+
 using Microsoft.AspNetCore.DataProtection;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNetCore.Identity
@@ -21,15 +23,21 @@ namespace Microsoft.AspNetCore.Identity
         /// </summary>
         /// <param name="dataProtectionProvider">The system data protection provider.</param>
         /// <param name="options">The configured <see cref="DataProtectionTokenProviderOptions"/>.</param>
-        public DataProtectorTokenProvider(IDataProtectionProvider dataProtectionProvider, IOptions<DataProtectionTokenProviderOptions> options)
+        /// <param name="logger">The logger used to log messages, warnings and errors.</param>
+        public DataProtectorTokenProvider(IDataProtectionProvider dataProtectionProvider,
+                                          IOptions<DataProtectionTokenProviderOptions> options,
+                                          ILogger<DataProtectorTokenProvider<TUser>> logger)
         {
             if (dataProtectionProvider == null)
             {
                 throw new ArgumentNullException(nameof(dataProtectionProvider));
             }
+
             Options = options?.Value ?? new DataProtectionTokenProviderOptions();
+
             // Use the Name as the purpose which should usually be distinct from others
-            Protector = dataProtectionProvider.CreateProtector(Name ?? "DataProtectorTokenProvider"); 
+            Protector = dataProtectionProvider.CreateProtector(Name ?? "DataProtectorTokenProvider");
+            Logger = logger ?? throw new ArgumentNullException(nameof(logger));
         }
 
         /// <summary>
@@ -56,6 +64,14 @@ namespace Microsoft.AspNetCore.Identity
         /// </value>
         public string Name { get { return Options.Name; } }
 
+        /// <summary>
+        /// Gets the <see cref="ILogger"/> used to log messages from the provider.
+        /// </summary>
+        /// <value>
+        /// The <see cref="ILogger"/> used to log messages from the provider.
+        /// </value>
+        public ILogger<DataProtectorTokenProvider<TUser>> Logger { get; }
+
         /// <summary>
         /// Generates a protected token for the specified <paramref name="user"/> as an asynchronous operation.
         /// </summary>
@@ -110,6 +126,7 @@ namespace Microsoft.AspNetCore.Identity
                     var expirationTime = creationTime + Options.TokenLifespan;
                     if (expirationTime < DateTimeOffset.UtcNow)
                     {
+                        Logger.InvalidExpirationTime();
                         return false;
                     }
 
@@ -117,31 +134,52 @@ namespace Microsoft.AspNetCore.Identity
                     var actualUserId = await manager.GetUserIdAsync(user);
                     if (userId != actualUserId)
                     {
+                        Logger.UserIdsNotEquals();
                         return false;
                     }
+
                     var purp = reader.ReadString();
                     if (!string.Equals(purp, purpose))
                     {
+                        Logger.PurposeNotEquals(purpose, purp);
                         return false;
                     }
+
                     var stamp = reader.ReadString();
                     if (reader.PeekChar() != -1)
                     {
+                        Logger.UnexpectedEndOfInput();
                         return false;
                     }
 
                     if (manager.SupportsUserSecurityStamp)
                     {
-                        return stamp == await manager.GetSecurityStampAsync(user);
+                        var isEqualsSecurityStamp = stamp == await manager.GetSecurityStampAsync(user);
+                        if (!isEqualsSecurityStamp)
+                        {
+                            Logger.SequrityStampNotEquals();
+                        }
+
+                        return isEqualsSecurityStamp;
                     }
-                    return stamp == "";
+
+
+                    var stampIsEmpty = stamp == "";
+                    if (!stampIsEmpty)
+                    {
+                        Logger.SecurityStampIsNotEmpty();
+                    }
+
+                    return stampIsEmpty;
                 }
             }
             // ReSharper disable once EmptyGeneralCatchClause
             catch
             {
                 // Do not leak exception
+                Logger.UnhandledException();
             }
+
             return false;
         }
 
@@ -189,4 +227,4 @@ namespace Microsoft.AspNetCore.Identity
             writer.Write(value.UtcTicks);
         }
     }
-}
+}

src/Identity/Core/src/LoggingExtensions.cs

@@ -0,0 +1,91 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+
+namespace Microsoft.Extensions.Logging
+{ 
+    internal static class LoggingExtensions
+    {
+        private static readonly Action<ILogger, Exception> _invalidExpirationTime;
+        private static readonly Action<ILogger, Exception> _userIdsNotEquals;
+        private static readonly Action<ILogger, string, string, Exception> _purposeNotEquals;
+        private static readonly Action<ILogger, Exception> _unexpectedEndOfInput;
+        private static readonly Action<ILogger, Exception> _securityStampNotEquals;
+        private static readonly Action<ILogger, Exception> _securityStampIsNotEmpty;
+        private static readonly Action<ILogger, Exception> _unhandledException;
+
+        static LoggingExtensions()
+        {
+            _invalidExpirationTime = LoggerMessage.Define(
+                eventId: new EventId(0, "InvalidExpirationTime"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: the expiration time is invalid.");
+
+            _userIdsNotEquals = LoggerMessage.Define(
+                eventId: new EventId(1, "UserIdsNotEquals"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: did not find expected UserId.");
+
+            _purposeNotEquals = LoggerMessage.Define<string, string>(
+                eventId: new EventId(2, "PurposeNotEquals"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: did not find expected purpose. '{ActualPurpose}' does not match the expected purpose '{ExpectedPurpose}'.");
+
+            _unexpectedEndOfInput = LoggerMessage.Define(
+                eventId: new EventId(3, "UnexpectedEndOfInput"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: unexpected end of input.");
+
+            _securityStampNotEquals = LoggerMessage.Define(
+                eventId: new EventId(4, "SecurityStampNotEquals"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: did not find expected security stamp.");
+
+            _securityStampIsNotEmpty = LoggerMessage.Define(
+                eventId: new EventId(5, "SecurityStampIsNotEmpty"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: the expected stamp is not empty.");
+
+            _unhandledException = LoggerMessage.Define(
+                eventId: new EventId(6, "UnhandledException"),
+                logLevel: LogLevel.Debug,
+                formatString: "ValidateAsync failed: unhandled exception was thrown.");
+        }
+
+        public static void InvalidExpirationTime(this ILogger logger)
+        {
+            _invalidExpirationTime(logger, null);
+        }
+
+        public static void UserIdsNotEquals(this ILogger logger)
+        {
+            _userIdsNotEquals(logger, null);
+        }
+
+        public static void PurposeNotEquals(this ILogger logger, string actualPurpose, string expectedPurpose)
+        {
+            _purposeNotEquals(logger, actualPurpose, expectedPurpose,  null);
+        }
+
+        public static void UnexpectedEndOfInput(this ILogger logger)
+        {
+            _unexpectedEndOfInput(logger, null);
+        }
+
+        public static void SequrityStampNotEquals(this ILogger logger)
+        {
+            _securityStampNotEquals(logger, null);
+        }
+
+        public static void SecurityStampIsNotEmpty(this ILogger logger)
+        {
+            _securityStampIsNotEmpty(logger, null);
+        }
+
+        public static void UnhandledException(this ILogger logger)
+        {
+            _unhandledException(logger, null);
+        }
+    }
+}