From 590958376e8f1cf37ca79ee754b9f8fbc2bd915b Mon Sep 17 00:00:00 2001 From: Arthur Irgashev Date: Tue, 25 Jun 2019 00:30:09 +0300 Subject: [PATCH] Add debugg logging for DataProtectorTokenProvider.ValidationAsync (#10739) --- ...osoft.AspNetCore.Identity.netcoreapp3.0.cs | 3 +- .../Core/src/DataProtectorTokenProvider.cs | 48 +++++++++- src/Identity/Core/src/LoggingExtensions.cs | 91 +++++++++++++++++++ 3 files changed, 136 insertions(+), 6 deletions(-) create mode 100644 src/Identity/Core/src/LoggingExtensions.cs diff --git a/src/Identity/Core/ref/Microsoft.AspNetCore.Identity.netcoreapp3.0.cs b/src/Identity/Core/ref/Microsoft.AspNetCore.Identity.netcoreapp3.0.cs index a08fa9b444..12a6baf67a 100644 --- a/src/Identity/Core/ref/Microsoft.AspNetCore.Identity.netcoreapp3.0.cs +++ b/src/Identity/Core/ref/Microsoft.AspNetCore.Identity.netcoreapp3.0.cs @@ -21,7 +21,8 @@ namespace Microsoft.AspNetCore.Identity } public partial class DataProtectorTokenProvider : Microsoft.AspNetCore.Identity.IUserTwoFactorTokenProvider where TUser : class { - public DataProtectorTokenProvider(Microsoft.AspNetCore.DataProtection.IDataProtectionProvider dataProtectionProvider, Microsoft.Extensions.Options.IOptions options) { } + public DataProtectorTokenProvider(Microsoft.AspNetCore.DataProtection.IDataProtectionProvider dataProtectionProvider, Microsoft.Extensions.Options.IOptions options, Microsoft.Extensions.Logging.ILogger> logger) { } + public Microsoft.Extensions.Logging.ILogger> 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; } } diff --git a/src/Identity/Core/src/DataProtectorTokenProvider.cs b/src/Identity/Core/src/DataProtectorTokenProvider.cs index b268cc142d..0340a21bbe 100644 --- a/src/Identity/Core/src/DataProtectorTokenProvider.cs +++ b/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 /// /// The system data protection provider. /// The configured . - public DataProtectorTokenProvider(IDataProtectionProvider dataProtectionProvider, IOptions options) + /// The logger used to log messages, warnings and errors. + public DataProtectorTokenProvider(IDataProtectionProvider dataProtectionProvider, + IOptions options, + ILogger> 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)); } /// @@ -56,6 +64,14 @@ namespace Microsoft.AspNetCore.Identity /// public string Name { get { return Options.Name; } } + /// + /// Gets the used to log messages from the provider. + /// + /// + /// The used to log messages from the provider. + /// + public ILogger> Logger { get; } + /// /// Generates a protected token for the specified as an asynchronous operation. /// @@ -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); } } -} \ No newline at end of file +} diff --git a/src/Identity/Core/src/LoggingExtensions.cs b/src/Identity/Core/src/LoggingExtensions.cs new file mode 100644 index 0000000000..0bb1661c15 --- /dev/null +++ b/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 _invalidExpirationTime; + private static readonly Action _userIdsNotEquals; + private static readonly Action _purposeNotEquals; + private static readonly Action _unexpectedEndOfInput; + private static readonly Action _securityStampNotEquals; + private static readonly Action _securityStampIsNotEmpty; + private static readonly Action _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( + 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); + } + } +}